背景
システムの処理速度を改善するために、ボトルネック解析を行う必要があった。
ボトルネック解析の方法と、プロファイリングに使用したperfの使用方法に関して調査を行った。
記事の目的
perfを使用し、ボトルネック解析を行う
perf
ここでは、perfの導入方法及び使用方法について記載する。
perfとは
perf(Performance analysis tools for Linux)とはLinuxカーネル2.6.31以降で使用可能なLinuxの性能解析ツールである。実行されているプロセス毎のCPU使用率やプロセス内で呼ばれている関数の割合などを調査できる。
利点
- gprofのように、プログラム作成時に専用のライブラリを入れたり、コンパイル時にオプションをつける必要がない
- フレームグラフにして、ビジュアライズできる
導入方法(Ubuntu編)
Ubuntu16.04へperfを導入する手順について記載する。- OSのカーネルバージョンを調べる
- $ uname -a
- Linux emptySet 4.4.0-116-generic #140-Ubuntu SMP Mon Feb 12 21:23:04 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
- 上記カーネルバージョンのlinux-toolsパッケージをインストールする
- $ sudo apt install linux-tools-<カーネルバージョン>
上記の場合、カーネルバージョンは「4.4.0-116-generic」である。
使用方法
perfの使用方法は、下記の通りである。- コマンド内のボトルネック解析を行う場合
- perfで記録しながらコマンドを実行する
- $ perf record コマンド
- perfで記録したファイルの内容を表示する(-i [ファイル名.data]オプションでファイル名指定可能)
- $ perf report
- Samples: 44 of event 'cpu-clock', Event count (approx.): 11000000
- Overhead Command Shared Object Symbol
- 11.36% ring_buffer_sam libc-2.23.so [.] vfprintf
- 9.09% ring_buffer_sam libc-2.23.so [.] __GI___libc_write
- 6.82% ring_buffer_sam libc-2.23.so [.] _IO_file_xsputn@@GLIBC_2.2.5
- 6.82% ring_buffer_sam [unknown] [k] 0xffffffff8184e9b5
- 6.82% ring_buffer_sam [unknown] [k] 0xffffffff8184ef5a
- 4.55% ring_buffer_sam ring_buffer_sample [.] std::mutex::unlock
- 4.55% ring_buffer_sam [unknown] [k] 0xffffffff81508f2b
- 2.27% ring_buffer_sam libc-2.23.so [.] _IO_file_write@@GLIBC_2.2.5
- 2.27% ring_buffer_sam libc-2.23.so [.] fprintf
- 2.27% ring_buffer_sam ring_buffer_sample [.] RingBuffer::getBufferSize
- 2.27% ring_buffer_sam ring_buffer_sample [.] main
- 2.27% ring_buffer_sam ring_buffer_sample [.] std::mutex::lock
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff810031e8
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff81087b91
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8109b061
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8109b069
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff811c3b76
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff81213c9a
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff81214ba0
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8140cbaf
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8140cbb3
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8140dee9
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8150410d
- 2.27% ring_buffer_sam [unknown] [k] 0xffffffff8150420f
- For a higher level overview, try: perf report --sort comm,dso
- システム全体のボトルネック解析を行う場合
- perfで記録する
- $ sudo perf record -ag
- perfで記録したファイルの内容を表示する
- $ perf report
- Samples: 181K of event 'cpu-clock', Event count (approx.): 45387500000
- Overhead Command Shared Object Symbol
- 59.48% swapper [kernel.kallsyms] [k] 0xffffffff810656d6
- 1.98% ring_buffer_sam [kernel.kallsyms] [k] 0xffffffff8109b061
- 0.91% compiz [kernel.kallsyms] [k] 0xffffffff810031e8
- 0.85% gnome-terminal- [kernel.kallsyms] [k] 0xffffffff8109d9e0
- 0.83% gnome-terminal- libglib-2.0.so.0.4800.2 [.] g_string_insert_uni
- 0.80% gnome-terminal- [kernel.kallsyms] [k] 0xffffffff810031e8
- 0.76% compiz libX11.so.6.3.0 [.] 0x0000000000026e60
- 0.65% gnome-terminal- libglib-2.0.so.0.4800.2 [.] g_utf8_get_char
- 0.57% compiz libX11.so.6.3.0 [.] 0x0000000000026e62
- 0.57% compiz libX11.so.6.3.0 [.] 0x0000000000026f22
- 0.57% kworker/u8:2 [kernel.kallsyms] [k] 0xffffffff8109c9fa
- 0.54% compiz libX11.so.6.3.0 [.] 0x0000000000026f20
- 0.45% ring_buffer_sam [kernel.kallsyms] [k] 0xffffffff810ac14d
- 0.44% gnome-terminal- libglib-2.0.so.0.4800.2 [.] g_string_append_uni
- 0.42% ring_buffer_sam libc-2.23.so [.] vfprintf
- 0.41% ring_buffer_sam [kernel.kallsyms] [k] 0xffffffff8184ef5a
- 0.41% ring_buffer_sam [kernel.kallsyms] [k] 0xffffffff8184e9b5
- 0.41% ring_buffer_sam libc-2.23.so [.] __GI___libc_write
- 0.38% ring_buffer_sam libc-2.23.so [.] _IO_file_xsputn@@GL
- 0.37% kworker/u8:1 [kernel.kallsyms] [k] 0xffffffff8109c9fa
- 0.36% gnome-terminal- libvte-2.91.so.0.4200.5 [.] 0x00000000000135b2
- For a higher level overview, try: perf report --sort comm,dso
- フレームグラフでボトルネック解析結果を可視化する場合
- フレームグラフ作成用のスクリプトをダウンロードする
- $ wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/stackcollapse-perf.pl
- $ wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/flamegraph.pl
- perfで記録する
- $ sudo perf record -ag
- perfで記録したファイルからフレームグラフを作成する
- $ sudo perf script> perf_data.txt
- $ perl stackcollapse-perf.pl perf_data.txt|perl flamegraph.pl > flamegraph.svg
- firefox ./flamegraph.svg
- timechartを取得する場合
- perfで記録する
- $ sudo perf timechart record
- perfで記録した結果ファイルをsvgファイル(タイムチャート)として出力する(-p [pid or プロセス名]オプションで特定のプロセスのみを抜き出せる)
- $ sudo perf timechart -o timechart.svg
- $ firefox ./timechart.svg
デフォルトで、記録結果ファイル「perf.data」が作成される。(-o [ファイル名.data]オプションでファイル名指定可能)
例: ring_buffer_sample(l.148をbuf.setBufferSize(1000);に変更した)の場合
上記の例の場合、vfprintf(標準出力)が処理量の11%を占めているため、標準出力を減らすことが高速化に有効であることがわかる。
例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合
上記の例の場合、swapper(スワッピング処理)が処理量の60%を占めているため、メモリの利用率をチェックする必要がある。
例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合

例: ring_buffer_sample(l.148をbuf.setBufferSize(100000);に変更した)を実行した状態で取得した場合

その他コマンド一覧
- perf top リアルタイムに関数単位でcpu使用率を閲覧できる
- $ perf top
- ---------------------------------------------------------------------------
- PerfTop: 260 irqs/sec kernel:61.5% exact: 0.0% [1000Hz
- cycles], (all, 2 CPUs)
- ---------------------------------------------------------------------------
- samples pcnt function DSO
- _______ _____ ______________________________ __________________
- 80.00 23.7% read_hpet [kernel.kallsyms]
- 14.00 4.2% system_call [kernel.kallsyms]
- 14.00 4.2% __ticket_spin_lock [kernel.kallsyms]
- 14.00 4.2% __ticket_spin_unlock [kernel.kallsyms]
- 8.00 2.4% hpet_legacy_next_event [kernel.kallsyms]
- 7.00 2.1% i8042_interrupt [kernel.kallsyms]
- 7.00 2.1% strcmp [kernel.kallsyms]
- 6.00 1.8% _raw_spin_unlock_irqrestore [kernel.kallsyms]
- ...
- $ perf list
- List of pre-defined events (to be used in -e):
- cpu-cycles OR cycles [Hardware event]
- instructions [Hardware event]
- cache-references [Hardware event]
- cache-misses [Hardware event]
- branch-instructions OR branches [Hardware event]
- branch-misses [Hardware event]
- bus-cycles [Hardware event]
- ...
- $ perf stat - make -j
- Performance counter stats for 'make -j':
- 8117.370256 task clock ticks # 11.281 CPU utilization factor
- 678 context switches # 0.000 M/sec
- 133 CPU migrations # 0.000 M/sec
- 235724 pagefaults # 0.029 M/sec
- 24821162526 CPU cycles # 3057.784 M/sec
- 18687303457 instructions # 2302.138 M/sec
- 172158895 cache references # 21.209 M/sec
- 27075259 cache misses # 3.335 M/sec
- Wall-clock time elapsed: 719.554352 msecs
備考
- Symbolが16進数標記で読めない場合、addr2lineコマンドで関数名を確認できる場合もある
まとめ
- perfを使用し、ボトルネック解析を行う方法について調査、記載した
参考文献
変更履歴
- 2019/09/29: 新規作成
- 2020/05/04: コマンド一覧追加