執筆者 : 西村 大助
1. はじめに
本稿では、ネットワークの受信処理を例に、perf を使った性能分析を行う方法を解説します。
提示している実行例やソースは、実行環境として（やや古い）Ubuntu18.04LTS（4.15.0-20-generic）を前提としていますが、他のバージョンでも基本的な考え方は変わりません。
2. perf 概説
具体的な例の前に、簡単に perf についてまとめておきます。
2.1 perf とは
Linux（主にカーネル）の性能に関する情報を収集、分析するためのツールです。
元々は、Linux カーネルから CPU のパフォーマンスカウンタ（PMU）1を利用し、性能について解析するツールとして開発されていましたが、トレース機能2やプロファイル機能3なども追加されています。
2.2 基本的な使い方
基本的には、性能データを採取し、採取した性能データを分析するという流れになります。
以下に、本稿で利用するものも含め、いくつか代表的なオプションやサブコマンドを示しますが、より詳しく知りたい方は、参考資料にも挙げている Perf Wiki や Linux perf Examples を参照してください。
性能データの採取
性能データの採取は perf record コマンドで行います。
引数として、実行するコマンドを指定すれば、そのコマンドの実行中の性能データの採取を行いますが、実行するコマンドを指定しない場合は、Ctrl-C で perf record の実行が止められるまでのデータを採取します4。
主なオプション
- -a: 全ての CPU のデータを採取します（デフォルトの動作）。
- -C/--cpu (cpu number): 採取するデータを、指定した CPU のデータに限定します。
- -g/--call-graph: バックトレース情報も採取します。
- -o (file name): 出力ファイル名を指定します（デフォルト：perf.data）。
トレースデータの採取
トレースデータの採取は perf record コマンドに、-e オプションで採取するイベントを指定して採取します（採取可能なイベントについては後述します）。採取したいイベントが複数ある場合は、-e オプションを繰り返し指定します。また、イベント名には '*'（ワイルドカード）も指定することができます。
以下の例では、スケジューラとネットワークに関するイベントのトレースデータを採取します。
# perf record -e sched:* -e net:*
- プロファイルデータの採取
プロファイルデータは perf record コマンドに、-F オプションでサンプリング頻度を指定して採取します。
以下の例では、99Hz5で CPU0 のプロファイルデータを、dwarf 情報に基づくバックトレース付きで採取します。
# perf record -F 99 -C 0 --call-graph dwarf
性能データの分析
性能データの分析には、perf report コマンドを使います。また、性能データの内容を、perf script コマンドを使って、他のスクリプトで解析するための情報として出力することも可能です。
それぞれの出力例については、具体例を用いて後述します。
2.3 採取可能なイベント
採取可能なイベントには、最初から組み込まれているイベントと、ユーザが定義するイベントがあります。
組み込みイベント
組み込みイベントには大きく以下のようなものがありますが、いずれも、perf list コマンドで一覧を表示できます（本稿では、static tracepoint 以外については触れません）。
- hardware event: キャッシュミスなど、ハードウェアの動作に起因するイベント。
- software event: ページフォルトなど、ソフトウェアの動作に起因するイベント。
- static tracepoint: カーネルにあらかじめ定義されている tracepoint。
（perf list コマンドの出力例）
# perf list List of pre-defined events (to be used in -e): branch-instructions OR branches [Hardware event] branch-misses [Hardware event] cache-misses [Hardware event] cache-references [Hardware event] ... major-faults [Software event] minor-faults [Software event] page-faults OR faults [Software event] ... net:netif_receive_skb [Tracepoint event] net:netif_receive_skb_entry [Tracepoint event] net:netif_rx [Tracepoint event] net:netif_rx_entry [Tracepoint event] net:netif_rx_ni_entry [Tracepoint event] ...
static tracepoint はソースコード内で、trace_***() といった関数として埋め込まれており、例えば、上記の net:netif_receive_skb イベントであれば、__netif_receive_skb_core() という関数に以下のように埋め込まれています6。
static int __netif_receive_skb_core(struct sk_buff *skb, bool pfmemalloc) { struct packet_type *ptype, *pt_prev; rx_handler_func_t *rx_handler; struct net_device *orig_dev; bool deliver_exact = false; int ret = NET_RX_DROP; __be16 type; net_timestamp_check(!netdev_tstamp_prequeue, skb); trace_netif_receive_skb(skb); ★ ...
ユーザ定義イベント（dynamic tracepoint）
static tracepoint としてあらかじめカーネル内に埋め込まれていない箇所でも、perf probe コマンドを使って、ユーザが好きな箇所に tracepoint を埋め込んで情報を取得することも可能です。tracepoint を埋め込む事ができる関数一覧は、-F オプションを指定して確認できます。
以下は、tracepoint を埋め込み可能なカーネル内の関数の一覧を取得する際の実行例です。
# perf probe -k /usr/lib/debug/boot/vmlinux-4.15.0-20-generic -F
以下のように、モジュール内の関数でも確認することができます。
# perf probe -m /usr/lib/debug/lib/modules/4.15.0-20-generic/kernel/drivers/net/ethernet/intel/e1000/e1000.ko -F
また、dynamic tracepoint では、取得する変数も指定することができ（static tracepoint では、取得される変数もあらかじめ定義されています）、取得可能な変数は、-V オプションに対象の関数を指定して確認できます。
以下は、process_backlog() という関数に tracepoint を埋め込む際に取得可能な変数を確認する例ですが、process_backlog() が呼び出された際の引数（@quota, @napi）などが取得可能であることがわかります。
（process_backlog() の定義）
static int process_backlog(struct napi_struct *napi, int quota) { struct softnet_data *sd = container_of(napi, struct softnet_data, backlog); bool again = true; int work = 0; ...
（perf probe 実行例）
# perf probe -k /usr/lib/debug/boot/vmlinux-4.15.0-20-generic -V process_backlog
Available variables at process_backlog
@
int quota
int work
struct napi_struct* napi
dynamic tracepoint を perf record で採取対象のイベントとするには、あらかじめ perf probe --add で追加しておく必要があります。
# perf probe -k /usr/lib/debug/boot/vmlinux-4.15.0-20-generic --add process_backlog
Added new event:
probe:process_backlog (on process_backlog)
You can now use it in all perf tools, such as:
perf record -e probe:process_backlog -aR sleep 1
追加済の dynamic tracepoint は、perf probe -l で確認することができます。
# perf probe -l probe:process_backlog (on process_backlog@linux-4.15.0/net/core/dev.c)
上記の例からもわかる通り、dynamic tracing のイベントには、probe:*** というイベント名がつけられるので、perf record コマンドに -e probe:* と指定すれば、追加した全ての dynamic tracepoint の情報が採取されます。
3. 具体例
例として、UDP パケットの送受信を行うアプリケーションを docker コンテナ内で起動した際の性能分析をしてみましょう。
以降の性能データの採取は、当該アプリケーションで常に送受信を行っている状態で行っています。
3.1 準備
perf を使って性能データを採取したり分析7したりするには、カーネルのデバッグモジュールが必要です。
本稿では Ubuntu18.04LTS（4.15.0-20-generic）を使用するので、Debug Symbol Packages - Ubuntu Wiki を参考に、linux-image-4.15.0-20-generic-dbgsym をインストールしています。
3.2 プロファイル
まずは、プロファイルデータを採取して、各処理の実行割合を確認してみましょう。
性能データの採取
以下のように、99Hz のプロファイルデータを、dwarf 情報に基づくバックトレース付きで、30秒間採取します。
# perf record -F 99 -a --call-graph dwarf -o perf.profile -- sleep 30 [ perf record: Woken up 23 times to write data ] [ perf record: Captured and wrote 7.428 MB perf.profile (997 samples) ]
性能データの分析
採取したデータ（perf.profile）を、perf report コマンドを使って分析してみましょう。
以下のように、NIC の割り込みが上がる CPU 2の情報を、コールトレース付きで見てみます。
# perf report -i perf.profile -C 2 --call-graph=graph,5 --stdio
...
99.96% 0.00% swapper [kernel.vmlinux] [k] ret_from_intr
|
---ret_from_intr
do_IRQ
|
|--82.05%--irq_exit
| |
| --78.55%--__softirqentry_text_start
| net_rx_action
| |
| |--52.71%--e1000_clean
| | |
| | |--34.28%--e1000_clean_rx_irq
| | | napi_gro_receive
| | | netif_receive_skb_internal
| | | __netif_receive_skb
| | | __netif_receive_skb_core
| | | ip_rcv
| | | |
| | | |--23.18%--nf_hook_slow
| | | | |
| | | | --18.17%--ipv4_conntrack_in
| | | | nf_conntrack_in
| | | |
| | | --11.10%--ip_rcv_finish
| | | ip_route_input_noref
| | | ip_route_input_rcu
| | | fib_validate_source
| | |
| | --11.30%--e1000_unmap_and_free_tx_resource.isra.46
| | __dev_kfree_skb_any
| | consume_skb
| | skb_release_all
| | skb_release_data
| |
| --25.84%--process_backlog
| |
| --12.55%--__netif_receive_skb
| __netif_receive_skb_core
| ip_rcv
| ip_rcv_finish
| ip_local_deliver
| ip_local_deliver_finish
| udp_rcv
| __udp4_lib_rcv
|
--17.91%--handle_irq
handle_fasteoi_irq
handle_irq_event
handle_irq_event_percpu
__handle_irq_event_percpu
|
--17.90%--e1000_intr
...
上記のように、ほぼ全て（99.96%）が割り込み処理に割かれていて、更に、そのうち、78.55% が soft IRQ 処理、17.91% が hard IRQ 処理であることがわかります。
プロファイルデータの利用例の１つとして、測定条件を変えて性能差が出た場合に、その性能差がどこから来ているかの当たりをつけるといったことが考えられます。
例えば、上記は docker コンテナでアプリケーションを動作させた場合のものですが、docker コンテナを使わずにホスト上で直接アプリケーションを動作させた場合のプロファイルデータの出力は以下のようになります。
100.00% 0.00% swapper [kernel.vmlinux] [k] ret_from_intr
|
---ret_from_intr
do_IRQ
|
|--70.73%--irq_exit
| |
| |--46.29%--__softirqentry_text_start
| | |
| | --46.29%--net_rx_action
| | e1000_clean
| | |
| | --42.02%--e1000_clean_rx_irq
| | napi_gro_receive
| | netif_receive_skb_internal
| | __netif_receive_skb
| | __netif_receive_skb_core
| | ip_rcv
| | |
| | |--21.01%--ip_rcv_finish
| | | ip_local_deliver
| | | ip_local_deliver_finish
| | | udp_rcv
| | | __udp4_lib_rcv
| | | udp_queue_rcv_skb
| | | __udp_enqueue_schedule_skb
| | | sock_def_readable
| | | __wake_up_sync_key
| | | __wake_up_common_lock
| | | __wake_up_common
| | | receiver_wake_function
| | | autoremove_wake_function
| | | default_wake_function
| | | try_to_wake_up
| | | native_smp_send_reschedule
| | | x2apic_send_IPI
| | | native_write_msr
| | |
| | --21.01%--nf_hook_slow
| | ipv4_conntrack_in
| | nf_conntrack_in
| | udp_error
| | nf_ip_checksum
| | __skb_checksum_complete
| | skb_checksum
| | __skb_checksum
| | csum_partial_ext
| | csum_partial
| | do_csum
| |
| --24.44%--tick_nohz_irq_exit
| irq_work_needs_cpu
|
--22.62%--irq_enter
tick_irq_enter
ほぼ全てが割り込み処理に割かれ、それが soft IRQ と hard IRQ に別れているのは同じですが、docker コンテナを利用した場合との大きな違いとして、soft IRQ 処理中の backlog の処理（process_backlog()）が無くなっている事がわかります。
詳細については本稿では触れませんが、この backlog の処理は、パケットが「物理NIC → ブリッジ(docker0) → veth → (コンテナの)eth0」と流れていく中の、最後「(コンテナの)eth0」 の受信処理に当たります（なので、docker コンテナを使用しない場合はプロファイルデータに現れないわけです）。
3.3 トレース
上記で、アプリケーションを docker コンテナ上で動作させた場合と、ホスト上で直接動作させた場合で、処理に違いがあることを見ましたが、ではその処理の違いによりどのくらいの性能差（遅延）が発生しているのでしょうか。
ここでは、処理の各ポイントに tracepoint を設定し、それぞれの tracepoint の時刻から遅延を計測してみたいと思います。
性能データの採取
今回の構成における受信処理の流れのイメージとしては以下の図のようになっています。
なので以下の関数に tracepoint を設定してみます。
- e1000_clean(): e1000 ドライバ8の NAPI のハンドラ9
- enqueue_to_backlog(): backlog へのパケットの追加処理
- process_backlog(): backlog に追加されているパケットの処理
- netif_receive_skb(): ネットワーク層の受信処理（net:netif_receive_skb で採取）
- dev_queue_xmit(): デバイスへの送信処理（net:net_dev_start_xmit で採取）
具体的には、以下のようにトレースデータを採取します。
# perf probe -m /usr/lib/debug/lib/modules/4.15.0-20-generic/kernel/drivers/net/ethernet/intel/e1000/e1000.ko --add e1000_clean # perf probe -k /usr/lib/debug/boot/vmlinux-4.15.0-20-generic --add 'enqueue_to_backlog skb' # perf probe -k /usr/lib/debug/boot/vmlinux-4.15.0-20-generic --add process_backlog # perf record -e net:netif_receive_skb -e net:net_dev_start_xmit -e probe:*
性能データの分析
上記の perf record で採取したデータ（perf.data）を、perf script で見てみると以下のようになっています（説明の都合上、行数を表示しています）。
# perf script -i perf.data
1 swapper 0 [002] 82163.532695: probe:e1000_clean: (ffffffffc001f3f0)
2 swapper 0 [002] 82163.532709: net:netif_receive_skb: dev=ens3 skbaddr=0xffff8801388b7500 len=46
3 swapper 0 [002] 82163.532776: net:net_dev_start_xmit: dev=docker0 queue_mapping=0 skbaddr=0xffff8801388b7500 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=0 len=58 data_len=0 network_offset=14 transport_offset_valid=1 transport_offset=34 tx_flags=0 gso_size=0 gso_segs=0 gso_type=0
4 swapper 0 [002] 82163.532782: net:net_dev_start_xmit: dev=vetha94aecc queue_mapping=0 skbaddr=0xffff8801388b7500 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=0 len=58 data_len=0 network_offset=14 transport_offset_valid=1 transport_offset=34 tx_flags=0 gso_size=0 gso_segs=0 gso_type=0
5 swapper 0 [002] 82163.532785: probe:enqueue_to_backlog: (ffffffff81847510) skb=0xffff8801388b7500
6 swapper 0 [002] 82163.532822: probe:process_backlog: (ffffffff81848b00)
7 swapper 0 [002] 82163.532823: net:netif_receive_skb: dev=eth0 skbaddr=0xffff8801388b7500 len=44
8 apl 8720 [003] 82163.532914: net:net_dev_start_xmit: dev=eth0 queue_mapping=0 skbaddr=0xffff8800bb73e900 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=3 len=58 data_len=0 network_offset=14 transport_offset_valid=1 transport_offset=34 tx_flags=0 gso_size=0 gso_segs=0 gso_type=0
9 apl 8720 [003] 82163.532918: probe:enqueue_to_backlog: (ffffffff81847510) skb=0xffff8800bb73e900
10 apl 8720 [003] 82163.532920: probe:process_backlog: (ffffffff81848b00)
11 apl 8720 [003] 82163.532921: net:netif_receive_skb: dev=vetha94aecc skbaddr=0xffff8800bb73e900 len=44
12 apl 8720 [003] 82163.532934: net:netif_receive_skb: dev=docker0 skbaddr=0xffff8800bb73e900 len=44
13 apl 8720 [003] 82163.532945: net:net_dev_start_xmit: dev=ens3 queue_mapping=0 skbaddr=0xffff8800bb73e900 vlan_tagged=0 vlan_proto=0x0000 vlan_tci=0x0000 protocol=0x0800 ip_summed=3 len=58 data_len=0 network_offset=14 transport_offset_valid=1 transport_offset=34 tx_flags=0 gso_size=0 gso_segs=0 gso_type=0
書式としては、プロセス名、PID、CPU番号、タイムスタンプ、イベント名、イベントデータの順となります。
上記の例では、1〜7行目が受信処理、8〜13行目がアプリケーションによる送信処理となっています（本稿では送信処理については触れません）。
出力されているタイムスタンプから、受信処理においては2〜3行間の 67us と、5〜6行間の 37us の遅延が比較的比重が大きいことがわかります。
ちなみに、前述の図と各行の対応は以下のような感じになっています（各行数を丸数字で表現）。
4. 最後に
簡単にではありますが perf の紹介と、ネットワークの受信処理に対して利用してみた例を説明してみましたが、いかがでしたでしょうか。
perf には本稿で挙げた以外にも様々な機能があるので、是非、参考資料なども参考に実際に動かしてみてください。
5. 参考資料
-
パフォーマンス監視ユニット。キャッシュミスやページフォルトなどのイベントをカウントできる。↩
-
プログラムであるイベント（例えば、ある関数が実行されるなど）が発生した際、発生した際の時刻や変数などを確認できる機能。↩
-
あるサンプリング周期にて、プログラムの実行箇所を記録する機能。↩
-
例えば、perf record (各種オプション) – sleep 60 とすれば 60 秒間の性能データを採取することもできます。↩
-
あえて中途半端な値にすることで、定期的なイベントを毎回検出してしまうようなことを避ける意味があります。↩
-
この trace_***() 系の関数はイベント名を引数にしたマクロで定義されています。↩
-
性能データを別ホストで分析したりする場合、同じカーネルバージョンの環境を用意する必要があります。↩
-
e1000 ドライバを使用する前提です。↩
-
厳密にはハードウェア割り込みから、NAPI のハンドラが起動されるまでの処理もあるのですが、ホストとコンテナで共通であり、本稿では割愛します。↩
