Linuxに関する性能問題に一緒に立ち向かってくれるperfという心強い味方
この記事はぴょこりんクラスタ:Re Advent Calendar 2016 - Adventarのために書いたものです。
サマリ
- perfというLinux性能問題に立ち向かうための強力なツールがあるのでみんな使おう！
- 今回は自分のよく使うperf top、perf record、perf scriptについて紹介するよ！
- manが詳しいので困ったらmanを読んだほうがいいよ！
背景
プログラムを作る上で、性能問題を回避することはできない。 自分のプログラムならトレースを仕掛ければいいんだけど、 OSが絡んでいたり、性能が出ないコードの書き方をしていたりするとトレースだけでは難しいこともある。 そんなとき、割と何でも見られるperfが役に立つこともあるかもしれない。
perfとは
Linux用のプロファイリング・トレーシングツール。 manを見ると"perf - Performance analysis tools for Linux"とあって、本当にそのままの名前。 ハードウェアのパフォーマンスカウンタを採取したり、カーネル内に仕掛けられたトレースポイントで 情報(カウントだけじゃなくトレースポイントに応じて)を取ったりできる。
perfのインストール
何も考えずにaptなりyumなりで入れられる。aptの場合はなぜかlinux-tools-genericに入っているので注意。自分でコンパイルしようとすると、Linuxのカーネルソースが必要な上に、いろいろ依存ライブラリが多くて面倒なのでおすすめはしない。
# Ubuntuの場合 $ sudo apt install linux-tools-generic # CentOSの場合 $ sudo yum install perf
とりあえずperf topで中を見てみる
perf topとは文字通りtopコマンドを関数単位で実行してくれるようなもので、プロファイリング結果をリアルタイムで覗けるツール。perf topをするとこんな感じ。 CentOSでいうところのdebuginfoが入っていないのでnodeやら何やらアドレス値しか見えないけど、debuginfoが入っているものや-g付きでコンパイルしたものは関数名が見える。
$ sudo perf top
perf topはデフォルトでCPUのサイクルをいちばん食っている(要は時間)もの上位を出力してくれるけど、
もちろん違う指標でプロファイリングもできるし、コアやプロセス、スレッド狙い撃ちもできる。
よく使いそうなオプションはこの辺ですかね。
-C <cpu-list>：デフォルトでシステム全体のところを、コアを狙い撃ちすることができる。-C 0-3とか、-C 0,1,2,3みたいに使う-p <pid>：PID指定。-p 0,1,2みたいに複数指定もできる-t <tid>：TID指定。TIDはps auxww -Lで確認しよう-u <uid|user_name>：uidもしくはuser_nameで指定したユーザが実行中のプロセスについて表示-c <count>：イベントが<count>回発生するごとに情報採取-f <freq>：プロファイリング周期-e <event>：プロファイルするイベント。ハードウェアのパフォーマンスカウンタ(例えばサイクル数とかキャッシュミス数とか)とか、カーネル内のトレースイベントを指定できる。
-e について
どんなものが指定できるか？
perf listで指定可能なイベントはほぼ全部見られる。ここで出てきた名前をそのまま-eオプションに渡してやればいい。
親切な名前がついているので、おおよそ名前の通りのイベントが取れる。
$ perf list List of pre-defined events (to be used in -e): branch-instructions OR branches [Hardware event] branch-misses [Hardware event] bus-cycles [Hardware event] cache-misses [Hardware event] cache-references [Hardware event] cpu-cycles OR cycles [Hardware event] instructions [Hardware event] ref-cycles [Hardware event] <中略> L1-dcache-load-misses [Hardware cache event] L1-icache-load-misses [Hardware cache event] L1-icache-loads [Hardware cache event] LLC-loads [Hardware cache event] LLC-prefetch-misses [Hardware cache event] LLC-prefetches [Hardware cache event] LLC-store-misses [Hardware cache event] LLC-stores [Hardware cache event] branch-load-misses [Hardware cache event] branch-loads [Hardware cache event] dTLB-load-misses [Hardware cache event] iTLB-load-misses [Hardware cache event] iTLB-loads [Hardware cache event] <以下略>
ハードウェアのイベントの指定方法について
"ほぼ全部"なのは、perf listには載っていないけどCPUのアーキテクチャ依存な直接指定できるイベントが存在するから。
man perf topを見ると、perf stat -e r1a8 -a sleep 1なんて例が載っているけど、CMASKとかINVとかの指定の仕方がわかりにくい*1ので、冗長だけどわかりやすい指定方法で指定すればいいと思う。
コアイベントだけじゃなく、uncoreイベントも同様に取れる。
# 以下の2つは同じ意味(のはず。CMASK指定してなさそうだし)。 # 最後のsleep 1は、1秒間だけ測定するときの定型句。 $ perf stat -e r1a8 -a sleep 1 $ perf stat -e cpu/event=0xa8,umask=0x1,name=LSD.UOPS,cmask=0/
ハードウェアのパフォーマンスカウンタに何があるか、どんな値を指定すればよいかは、IntelのDeveloper's Manual Vol.3Bを見よう。
perf recordとperf script
perf recordは文字通りハードウェアのイベント/ソフトウェアのトレースポイントでのイベントを採取してくれるもの。ソフトウェアのトレースポイントと言うのは、例えば、割り込みハンドラがいつ動いたかとか、どのプロセスからどのプロセスへコンテキストスイッチしたか、等々が該当する。
例として、結構よく取られそうなスケジューリング関連の統計情報イベントを取ってみる。
スケジューリング関係のイベントは、perf listで見たときに全部sched:というprefixがついているのでわかりやすい。
その中の統計情報イベントはsched:sched_stat_xxxxという形式で書かれている。
$ sudo perf list | grep sched: | grep stat sched:sched_stat_blocked [Tracepoint event] sched:sched_stat_iowait [Tracepoint event] sched:sched_stat_runtime [Tracepoint event] sched:sched_stat_sleep [Tracepoint event] sched:sched_stat_wait [Tracepoint event] sched:sched_stick_numa [Tracepoint event]
スケジューリング関連の統計情報イベントを5秒間採取するには、以下のコマンドを打てばOK。 以下のコマンドを実行すると、カレントディレクトリにperf.dataというバイナリファイルができあがっている*2。イベント間にスペース入れると実行できなくなるので注意*3。
# -aはシステム全体を情報採取対象とするオプション、-Tはタイムスタンプをつけるオプション $ sudo perf record -T -a -e sched:sched_stat_blocked,sched:sched_stat_iowait,sched:sched_stat_runtime,sched:sched_stat_sleep,sched:sched_stat_wait,sched:sched_stick_numa -- sleep 5
perf.dataができたら、perf scriptで中身を見てみよう。いっぱい行があって、"なるほど、わからん"という気分だと思う。
perf 25665 [000] 10703.314496: sched:sched_stat_runtime: comm=perf pid=25665 runtime=668711 [ns] vruntime=4029076279864 [ns] perf 25665 [000] 10703.314522: sched:sched_stat_runtime: comm=perf pid=25665 runtime=26659 [ns] vruntime=4029076306523 [ns] rcu_sched 10 [000] 10703.314524: sched:sched_stat_runtime: comm=rcu_sched pid=10 runtime=2203 [ns] vruntime=4029072613356 [ns] rcu_sched 10 [000] 10703.314525: sched:sched_stat_runtime: comm=rcu_sched pid=10 runtime=1190 [ns] vruntime=4029072614546 [ns] sleep 25666 [000] 10703.314970: sched:sched_stat_runtime: comm=sleep pid=25666 runtime=444092 [ns] vruntime=4029073055245 [ns] sleep 25666 [000] 10703.315009: sched:sched_stat_runtime: comm=sleep pid=25666 runtime=39401 [ns] vruntime=4029073094646 [ns] rcuos/0 11 [000] 10703.315042: sched:sched_stat_runtime: comm=rcuos/0 pid=11 runtime=32519 [ns] vruntime=4029072643672 [ns] rcuos/0 11 [000] 10703.315043: sched:sched_stat_runtime: comm=rcuos/0 pid=11 runtime=1479 [ns] vruntime=4029072645151 [ns] rcu_sched 10 [000] 10703.315044: sched:sched_stat_runtime: comm=rcu_sched pid=10 runtime=1413 [ns] vruntime=4029072615959 [ns] rcu_sched 10 [000] 10703.318039: sched:sched_stat_runtime: comm=rcu_sched pid=10 runtime=5552 [ns] vruntime=4029072621511 [ns] rcu_sched 10 [000] 10703.318040: sched:sched_stat_runtime: comm=rcu_sched pid=10 runtime=2378 [ns] vruntime=4029072623889 [ns] rcuos/0 11 [000] 10703.318047: sched:sched_stat_runtime: comm=rcuos/0 pid=11 runtime=6431 [ns] vruntime=4029072651582 [ns] memballoon 8171 [000] 10703.512849: sched:sched_stat_runtime: comm=memballoon pid=8171 runtime=67601 [ns] vruntime=4029072678754 [ns]
おおよそ察しはつくかもしれないけど、単にperf scriptを実行したときのsched_stat_runtimeのフォーマットはこんな感じ。
<プロセス名> <PID> [<コア番号>] <タイムスタンプ>: <イベント名>: comm=<実行中コマンド名> pid=<PID> runtime=<RUNNING状態だった時間> vruntime=<Linuxのスケジューラがスケジューリングに使う仮想的な時間>
runtimeは(たぶん)RUNNING状態だった時間であって、プログラムが動作し続けていた時間と必ずしも等しいわけじゃないことに注意されたし*4。vruntimeはスケジューラが使う仮想的な時間なので見てもあまり意味がない*5。
perf scriptにオレオレスクリプトでデータ整形してもらう
perf scriptはベタに結果を出力する機能以外にも、自分で作った整形スクリプト(言語はPerlもしくはPython)を使ってくれるという便利機能がある。 手順は以下の3ステップ。
例えば、runtimeの合計と平均を出すにはこんな感じ。
さいごに
perfは大変便利な道具ですが、道具に振り回されないようにがんばる必要がありますね。
