前回は eBPF を利用するために bcc を導入しました。本来 bcc は自分でプログラムを書くことが前提ですが、標準で添付されているツール群だけでもかなり面白いことがわかります。ただ添付されているコマンドだけでも 100 以上あるので全部取り上げることはできませんが、bcc Tutorial に取り上げられているコマンドだけでも色々面白いことがわかるのでご紹介したいと思います。
execsnoop
このコマンドは前回の動作確認にも使用しました。プログラムの実行を記録するものです。
$ sudo /usr/share/bcc/tools/execsnoop
PCOMM PID PPID RET ARGS
dhclient-script 19826 2318 0 /usr/sbin/dhclient-script
hostname 19828 19827 0 /bin/hostname
cat 19830 19829 0 /bin/cat /proc/cmdline
cat 19832 19831 0 /bin/cat /proc/cmdlinebcc Tutorial にも記載がある通り、起動して直ぐ終了してしまうがたくさん起動されているコマンドが負荷の原因になっている場合は、ps や top などで見つけにくいため、こういうツールが必要になります。似たようなコマンドに psacct があります。
opensnoop
どのプロセスがどのファイルを開いているのかがわかります。意外とこれをながめているだけでわかることも多いです。
$ sudo ./opensnoop
PID COMM FD ERR PATH
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommands
30697 opensnoop -1 2 /usr/lib64/python2.7/encodings/ascii.so
30697 opensnoop -1 2 /usr/lib64/python2.7/encodings/asciimodule.so
30697 opensnoop 12 0 /usr/lib64/python2.7/encodings/ascii.py
30697 opensnoop 13 0 /usr/lib64/python2.7/encodings/ascii.pyc
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommands
1968 irqbalance 6 0 /proc/interrupts
1968 irqbalance 6 0 /proc/stat
1968 irqbalance 6 0 /proc/irq/24/smp_affinity
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommands
29112 pickup 12 0 maildrop
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommands
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommands
2513 amazon-ssm-agen 8 0 /proc/sys/kernel/hostname
2513 amazon-ssm-agen 11 0 /var/lib/amazon/ssm/localcommandsxfsslower
ここでは、Amazon Linux 2 の標準ファイルシステムが xfs なので、xfsslower を取り上げますが、ext4 の ext4slower などもあります。
どんなコマンドかと言うと指定した時間以上IOに時間がかかった場合にそのコマンド名とファイル名を表示してくれるコマンドです。
なんかプロセスが遅いなぁという時にファイルIOがボトルネックになることがあるので、問題の切り分けにログを取っておくと有効かもしれません。
以下の実行例では dd コマンドで無理やり 10ms 以上のレイテンシを作っています。
$ sudo ./xfsslower
Tracing XFS operations slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
06:52:38 dd 29540 W 41943040 0 15.22 aa
06:53:10 dd 29541 W 41943040 0 15.20 aa
06:53:19 dd 29542 W 41943040 0 15.23 aa
06:53:24 dd 29543 W 41943040 0 15.13 aa
06:53:26 dd 29544 W 41943040 0 15.31 aa
06:53:29 dd 29545 W 41943040 0 15.16 aa
06:53:43 dd 29597 W 41943040 0 15.16 aabiolatency
diskio のレイテンシを表示してくれます。単純な iostat よりも詳細な情報を得ることができます。 レイテンシの分布状況から、ディスクアクセスの状況を知るのに役立ちます。
できれば、IOサイズとのクロス集計にすると面白いかもしれません。
$ sudo ./biolatency
Tracing block device I/O... Hit Ctrl-C to end.
^C
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 1 | |
32 -> 63 : 1 | |
64 -> 127 : 0 | |
128 -> 255 : 0 | |
256 -> 511 : 21 |********** |
512 -> 1023 : 59 |****************************** |
1024 -> 2047 : 13 |****** |
2048 -> 4095 : 70 |************************************ |
4096 -> 8191 : 77 |****************************************|cachestat
ディスクキャッシュのヒット率がわかります。またダーティページの状況がわかります。ディスクキャッシュにヒットするかどうかは性能に大きく関わるので、とても有効です。
もしディスクIOが多くて、キャッシュヒット率が低いようならば、メモリの増強を検討するなどの施策が必要になります。
$ sudo ./cachestat
HITS MISSES DIRTIES HITRATIO BUFFERS_MB CACHED_MB
0 0 0 0.00% 2 398
0 0 0 0.00% 2 398
0 0 0 0.00% 2 398
992 0 0 100.00% 2 398
0 0 0 0.00% 2 398
0 0 0 0.00% 2 398
0 0 0 0.00% 2 398
0 0 0 0.00% 2 398
1041 0 0 100.00% 2 398
0 0 0 0.00% 2 398
0 0 10240 0.00% 2 398runqlat
プロセスがCPUを待っている時間の分布を表示してくれます。もしこの分布が長い時間の方に長くなっている場合は CPU の増強が必要かもしれません。また定常的に監視するのであれば runqslower の方が良いかもしれません。
$ sudo ./runqlat
Tracing run queue latency... Hit Ctrl-C to end.
^C
usecs : count distribution
0 -> 1 : 29 |******* |
2 -> 3 : 146 |****************************************|
4 -> 7 : 120 |******************************** |
8 -> 15 : 43 |*********** |
16 -> 31 : 4 |* |
32 -> 63 : 3 | |
64 -> 127 : 4 |* |とりあえず、このぐらいで。また実際に適用した事例などがあれば紹介したいと思います。
