はじめに
この記事は詳解システムパフォーマンスの perf の章をもとに自分なりの理解をまとめたものです。
perf
perf は Linux のトレーシングツールであり、様々なイベントをトレースできる。
perf のサブコマンドをまとめると以下 (詳解システムパフォーマンスの図を当方にて描画したもの)
┌────────────────────┐
│ kernel │
│ ┌───────┐ │ ┌───────────┐
│ │ event ┼─────────┼────►│ perf list ├──────────► event list(text)
│ └───┬─┬─┘ │ └───────────┘
│ │ │ ┌───────┐│ ┌───────────┐
│ │ └─►│counter┼┼────►│ perf stat │ ─────────► counter(text)
│ ▼ └───────┘│ └───────────┘
│┌───────────┐ │ ┌────────────┐
││ring buffer├───────┼────►│ perf trace ├─────────► sample(text)
│└─────┬─────┘ │ └────────────┘
└──┬───┼─────────────┘
│ │ ┌─────────────┐
│ └──────────────────►│ perf record │──►perf.data───────┐
│ └─────────────┘ │ ┌─────────────┐
│ ▲ │ │ perf report │────► summary(text)
│ ┌────────────┐ │ ▼ └─────────────┘
└────────►│ perf probe ┼────────┘ ┌─────────────┐
└────────────┘ │ perf script │──────────────────► sample(text)
└─────────────┘
└──────────────────────────► frame graph(svg)
kernel 5.8+また、perf は NMI 割り込みで行われる。 この説明はこのブログがわかりやすい。 つまり、ハード割り込みコンテキストでも NMI 割り込みは行われるため、大量に NMI 割り込みが行われるとパフォーマンスに影響が出る。そのためサンプリングレートには気を使う必要がある。
どういうときに perf を使うのか
高度なトラブルシューティング、パフォーマンス改善に役立ちます。 なぜカーネル側の負荷が高いのか？どこのコードでメモリを多く割り当ててるのか？など
よく使いそうなコマンド集は以下にある。
perf list
トレースできるイベントは以下のコマンドで確認ができる。
> perf list
List of pre-defined events (to be used in -e or -M):
alignment-faults [Software event]
bpf-output [Software event]
cgroup-switches [Software event]
context-switches OR cs [Software event]
cpu-clock [Software event]
cpu-migrations OR migrations [Software event]
dummy [Software event]
emulation-faults [Software event]
major-faults [Software event]
minor-faults [Software event]
page-faults OR faults [Software event]
task-clock [Software event]
...perf list の後に単語を入力すると grep できる。
> perf list kernel
List of pre-defined events (to be used in -e or -M):
exceptions:page_fault_kernel [Tracepoint event]
なお、ソフトウェアイベントはカーネルのコンテキストから数え、ハードウェアイベントは PMC レジスタから数える。 また、トレースポイントイベントはカーネルに配置されたトレースポイントの他、kprobe、uprobe ベースのトレースポイントも含まれる。
perf stat
また、perf stat コマンドでは PMC (Performance Monitoring Counter) 統計を表示してくれる。 これでイベントの発生回数、頻度、そもそも発生しているかを確認できる。
例として、1秒間で kmalloc が発生した回数を計測するには以下で可能。
> perf stat -e kmem:kmalloc -a sleep 1
Performance counter stats for 'system wide':
612 kmem:kmalloc
1.001437064 seconds time elapsedオプションの意味は man page を参照
perf trace
perf trace はライブでそのトレースを表示してくれる。
> perf trace -e syscalls:sys_enter_clone
...
12519.012 zsh/2557076 syscalls:sys_enter_clone(clone_flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_tidptr: 0x7f57946e0a10)
12534.335 zsh/2557057 syscalls:sys_enter_clone(clone_flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_tidptr: 0x7f57946e0a10)
12534.716 zsh/2557057 syscalls:sys_enter_clone(clone_flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_tidptr: 0x7f57946e0a10)
12534.902 zsh/2557111 syscalls:sys_enter_clone(clone_flags: CHILD_CLEARTID|CHILD_SETTID|0x11, child_tidptr: 0x7f57946e0a10)
...またどのようなフォーマットで出力されるかは /sys/kernl/debug/tracing/events/ ディレクトリ以下で定義される。
> cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_clone/format
name: sys_enter_clone
ID: 119
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int __syscall_nr; offset:8; size:4; signed:1;
field:unsigned long clone_flags; offset:16; size:8; signed:0;
field:unsigned long newsp; offset:24; size:8; signed:0;
field:int * parent_tidptr; offset:32; size:8; signed:0;
field:int * child_tidptr; offset:40; size:8; signed:0;
field:unsigned long tls; offset:48; size:8; signed:0;
print fmt: "clone_flags: 0x%08lx, newsp: 0x%08lx, parent_tidptr: 0x%08lx, child_tidptr: 0x%08lx, tls: 0x%08lx", ((unsigned long)(REC->clone_flags)), ((unsigned long)(REC->newsp)), ((unsigned long)(REC->parent_tidptr)), ((unsigned long)(REC->child_tidptr)), ((unsigned long)(REC->tls))perf record
perf record は perf trace と違い、イベントの記録をファイルに書き込んであとで分析できるようにする。 デフォルトでは perf.data というファイルで出力される。
> perf record -g -e syscalls:sys_enter_clone
^C[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.483 MB perf.data (70 samples) ]記録したイベントを perf report や perf script で解析する。
perf report
保存したイベントを TUI 形式で表示してくれます。
Samples: 70 of event 'syscalls:sys_enter_clone', Event count (approx.): 70
Children Self Command Shared Object Symbol
+ 80.00% 80.00% setup-policy-ro libc.so.6 [.] _Fork
+ 12.86% 12.86% insertDriver.sh libc.so.6 [.] _Fork
+ 4.29% 4.29% removeDriver.sh libc.so.6 [.] _Fork
+ 2.86% 2.86% systemd libc.so.6 [.] _Fork各イベントを選択することでさらに詳細な解析ができます。
perf script
各サンプルごとに詳細を確認できます。
> perf script | head
systemd 1 [000] 1398151.113155: syscalls:sys_enter_clone: clone_flags: 0x01200011, newsp: 0x00000000, parent_tidptr: 0x00000000, child_tidptr: 0x7f6b7f00ae10, tls: 0x00000000
118a47 _Fork+0x27 (/usr/lib64/libc.so.6)
setup-policy-ro 2579262 [002] 1398151.198919: syscalls:sys_enter_clone: clone_flags: 0x01200011, newsp: 0x00000000, parent_tidptr: 0x00000000, child_tidptr: 0x7f2a6c4aea10, tls: 0x00000000
118a47 _Fork+0x27 (/usr/lib64/libc.so.6)
setup-policy-ro 2579262 [002] 1398151.200560: syscalls:sys_enter_clone: clone_flags: 0x01200011, newsp: 0x00000000, parent_tidptr: 0x00000000, child_tidptr: 0x7f2a6c4aea10, tls: 0x00000000
118a47 _Fork+0x27 (/usr/lib64/libc.so.6)各エントリは左から、プロセス名、スレッドID、CPU ID、タイムスタンプ、イベント名、イベント引数
—header オプションを付ければ perf.data のメタデータも出力できる。
> perf script --header
# ========
# captured on : Sun Mar 23 10:24:30 2025
# header version : 1
# data offset : 456
# data size : 505944
# feat offset : 506400
# hostname : AL2023
# os release : 6.1.129-138.220.amzn2023.x86_64
# perf version : 6.1.129-138.220.amzn2023.x86_64
# arch : x86_64
# nrcpus online : 4
# nrcpus avail : 4
...また、 perf script -l コマンドでリストできるサブコマンドも使える。
> perf script -l
List of available trace scripts:
failed-syscalls [comm] system-wide failed syscalls
rw-by-file <comm> r/w activity for a program, by file
rw-by-pid system-wide r/w activity
rwtop [interval] system-wide r/w top
wakeup-latency system-wide min/max/avg wakeup latency
...perf probe
動的トーレスポイントを定義するコマンド。 kprobe、uprobe、USDT プローブをまとめてプローブイベントと呼び、これらは動的なトレースポイントであり、デフォルトでは perf list に含まれない。
例として、kprobe を使い、do_nanosleep( )カーネル関数をインストルメンテーションする。
> perf probe --add do_nanosleep
Added new event:
probe:do_nanosleep (on do_nanosleep)
You can now use it in all perf tools, such as:
perf record -e probe:do_nanosleep -aR sleep 1
> perf list "probe:*"
List of pre-defined events (to be used in -e or -M):
probe:do_nanosleep [Tracepoint event]
> perf record -e probe:do_nanosleep -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.349 MB perf.data (134 samples) ]
> perf report --stdio
# To display the perf.data header info, please use --header/--header-only opt>
#
#
# Total Lost Samples: 0
#
# Samples: 134 of event 'probe:do_nanosleep'
# Event count (approx.): 134
#
# Overhead Command Shared Object Symbol
# ........ .......... ................ ................
#
54.48% chronicled [kernel.vmlinux] [k] do_nanosleep
44.78% esbuild [kernel.vmlinux] [k] do_nanosleep
0.75% sleep [kernel.vmlinux] [k] do_nanosleep
...同じように uprobe を使って任意の関数をインストルメンテーションできる。
> perf probe -x /lib64/libc.so.6 --add fopen
Added new event:
probe_libc:fopen (on fopen in /usr/lib64/libc.so.6)
You can now use it in all perf tools, such as:
perf record -e probe_libc:fopen -aR sleep 1
> perf record -e probe_libc:fopen -aR sleep 1
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.338 MB perf.data (1 samples) ]
> perf script
sleep 2600568 [000] 1408770.938375: probe_libc:fopen: (7fe09c88c130)