bcc に添付されている便利ツール色々

前回は 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/cmdline

bcc 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/localcommands

xfsslower

ここでは、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 aa

biolatency

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        398

runqlat

プロセスが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        |*                                       |

とりあえず、このぐらいで。また実際に適用した事例などがあれば紹介したいと思います。