Ubuntu Weekly Recipe

第688回 eBPFのコンパイラーに対応したツールでさまざまな挙動を可視化する

この記事を読むのに必要な時間:およそ 8.5 分

BCCの便利なツールたち

現状のBCCには,100個以上のツールが用意されています。これをすべて網羅するのは難しいのですが,よく使いそうな便利なものをいくつかピックアップして紹介しましょう。ちなみに公式サイトのREADME.mdに掲載されているレイヤーごとの担当ツール一覧の図を見るだけで,おおよその関係がつかめるはずです。

なお,これらのツールのほとんどはPythonプログラムです。よってその中身を見れば,容易にカスタマイズ可能になっています。

特定のイベントを監視するsnoop系ツール

特定のイベントが発生したときに順次記録していくツールは「なんとかsnoop」という名前がつけられています。

その中でもexecsnoopやopensnoop,bindsnoop,mountsnoop,shmsnoop,statsnoop,syncsnoop,threadsnoopなどは,特定のシステムコールの呼び出しを記録するツールです。

たとえばexecsnoopは,その名の通りexec()システムコールの呼び出しを検知します。いわゆるpsコマンドは「実行した時点で動いているプロセス」しか確認できません。基本的なコマンドでプロセスが起動していく流れを確認しようと思ったら,psを定期的に実行するなりtopを眺めるなりする必要があります。execsnoopを使うと,瞬間的に起動したプログラムも含めてすべてのプロセスの起動の流れが把握できます。⁠特定の期間において何が起きているか」を知るためには強力なツールです。

コマンド自体は引数なしで起動するだけでも十分に使えます。-Tで時刻情報を,-UでUIDを,-xexec()が失敗した場合も記録してくれます。

$ sudo execsnoop-bpfcc -UTx
TIME     UID   PCOMM            PID     PPID    RET ARGS
01:07:55 1000  sh               2109659 4089    0   /bin/sh -c byobu-status tmux_left
01:07:55 1000  byobu-status     2109660 2109659 0   /usr/bin/byobu-status tmux_left
01:07:55 1000  sed              2109662 2109660 0   /usr/bin/sed --follow-symlinks s/// /dev/null
01:07:55 1000  sh               2109661 4089    0   /bin/sh -c byobu-status tmux_right

逆にプロセスの終了を検知したい場合はexitsnoopやkillsnoopが使えます。

もうひとつよく使う可能性があるのがopen()システムコールを検知する,opensnoopでしょう。ただしLinuxシステムではいろいろなプロセスがいろいろなファイルを開きながら動いているため,単に出力すると膨大なログになってしまいます。適宜PIDやプロセス名でフィルタリングすると良いでしょう。

$ sudo opensnoop-bpfcc -U -u 1000
UID   PID    COMM               FD ERR PATH
1000  572612 chrome            179   0 /dev/shm/.com.google.Chrome.jX9pnM
1000  4089   tmux: server       19   0 /proc/2113318/cmdline
1000  3449   gnome-shell        91   0 /proc/self/stat
1000  3694   multipass.gui      20   0 /home/shibata/snap/multipass/5309/config/multipass/multipass.conf
1000  3694   multipass.gui      20   0 /home/shibata/snap/multipass/5309/config/multipass/multipass.conf

他にもbiosnoopやdcsnoopはブロックデバイスのI/Oやキャッシュイベントを監視できますし,カーネルのレイヤーに合わせていくつかのsnoop系ツールが用意されています。

定期的に描画を更新するtop系ツール

snoopが発生したイベントをそのままシーケンシャルに表示し続けるのに対して,topコマンドのように整形した上で表示したり,画面内の表示を更新するツールは「なんとかtop」という名前がつけられています。

  • biotop:ブロックI/Oのイベントを表示
  • filetop:ファイルのI/Oとそれを行うプロセスを表示
  • dirtop:特定のディレクトリ以下のI/Oを表示
  • cachetop:ページキャッシュのヒット/ミスなど統計情報を表示
  • slabratetop:Kernelのメモリアロケーションの情報を表示
  • netqtop:指定したNICのキューの情報を表示
  • tcptop:プロセスごとのTCPの送受信のスループットを表示

期間中に取得した情報の統計を表示するdist系ツール

perfコマンドのように一定期間情報を取得し,期間終了時にヒストグラムのように統計を図として表示するツールは「なんとかdist」という名前がつけられています。

  • argdist:指定した関数の呼び出しとその引数に応じたヒストグラムの表示
  • cpudist:タスクごとにCPUがオンになった期間に応じたヒストグラムの表示
  • ext4dist/btrfsdist/nfsdis/xfsdist/zfsdist:ファイルシステムのレイテンシーのヒストグラムの表示

たとえばkmalloc()に渡されたサイズごとのヒストグラムは次のように表示します。これはargdist --helpに載っている例です。

$ sudo argdist-bpfcc -H 'p::__kmalloc(u64 size):u64:size'
[02:08:08]
     size                : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 74       |***********                             |
        16 -> 31         : 30       |****                                    |
        32 -> 63         : 65       |**********                              |
        64 -> 127        : 13       |**                                      |
       128 -> 255        : 88       |*************                           |
       256 -> 511        : 260      |****************************************|
       512 -> 1023       : 57       |********                                |
      1024 -> 2047       : 3        |                                        |

ext4distなどのファイルシステム系のツールは操作ごとに整形して表示してくれます。

$ sudo ext4dist-bpfcc
operation = open
     usecs               : count     distribution
         0 -> 1          : 2038     |****************************************|
         2 -> 3          : 95       |*                                       |
         4 -> 7          : 30       |                                        |
         8 -> 15         : 1        |                                        |
        16 -> 31         : 1        |                                        |

operation = fsync
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |****************************************|
      1024 -> 2047       : 1        |****************************************|
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 0        |                                        |
      8192 -> 16383      : 1        |****************************************|

operation = write
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 282      |************************                |
         4 -> 7          : 463      |****************************************|
         8 -> 15         : 27       |**                                      |
        16 -> 31         : 14       |*                                       |
        32 -> 63         : 37       |***                                     |
        64 -> 127        : 9        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 0        |                                        |
      8192 -> 16383      : 0        |                                        |
     16384 -> 32767      : 0        |                                        |
     32768 -> 65535      : 1        |                                        |

operation = read
     usecs               : count     distribution
         0 -> 1          : 3714     |****************************************|
         2 -> 3          : 170      |*                                       |
         4 -> 7          : 32       |                                        |
         8 -> 15         : 9        |                                        |
        16 -> 31         : 5        |                                        |

またfilelatencyやbiolatencyのように,レイテンシーをヒストグラム表示するツールも存在します。

時間がかかっている処理だけを見つけるslower系ツール

特定のしきい値よりも時間のかかっている処理を見つけるためのツールは「なんとかslower」という名前が付いています。

こちらはdistのようにファイルシステムだけでなく,mysqld_qslowerdbslowerのように,データベース向けのツールも用意されているのが特徴です。

特にfuncslowerはカーネル上の特定の関数で時間がかかっているものを見つける際に,役に立ちます。

特定の言語に特化したツール

uflowやucallsなど,⁠uなんとか」なツールは特定の高級言語向けのトレーシングに特化した機能を備えています。

たとえばuflowは言語ごとのメソッド呼び出しのトレースを表示してくれます。

$ sudo uflow -l python 2168801
CPU PID     TID     TIME(us) METHOD
1   2168801 2168801 18.819   <- /usr/lib/python3/dist-packages/dbus/connection.py.msg_reply_handler
1   2168801 2168801 18.820   -> /usr/lib/python3/dist-packages/dbus/connection.py.msg_reply_handler
1   2168801 2168801 18.820     -> /usr/lib/python3/dist-packages/dbus/proxies.py._introspect_reply_handler
1   2168801 2168801 18.820       -> /usr/lib/python3/dist-packages/dbus/_expat_introspect_parser.py.process_introspection_data
1   2168801 2168801 18.820         -> /usr/lib/python3/dist-packages/dbus/_expat_introspect_parser.py.__init__
1   2168801 2168801 18.820         <- /usr/lib/python3/dist-packages/dbus/_expat_introspect_parser.py.__init__
1   2168801 2168801 18.820         -> /usr/lib/python3/dist-packages/dbus/_expat_introspect_parser.py.parse

それに対してucallsは一定期間内におけるメソッドの呼び出し回数をまとめてくれます。

$ sudo ucalls -l python 2168801
METHOD                                              # CALLS
/usr/lib/python3/dist-packages/UpdateManager/UpdatesAvailable.py.get_restart_icon        1
/usr/lib/python3/dist-packages/UpdateManager/Dialogs.py.on_settings_button_clicked        1
/usr/lib/python3/dist-packages/UpdateManager/Core/UpdateList.py._init_deps        1
/usr/lib/python3.9/re.py.compile                          1

-lに渡せるオプションはjava,perl,php,python,ruby,tcl,noneとなります。⁠none」の場合,単にシステムコールを対象とするだけです。

ちなみに「pythoncalls」コマンドは「ucall -l python」を呼び出すだけとなっています。

その他のツール

ここまでは比較的同じ系統としてまとまっていそうなものを紹介してきましたが,正直な話,ここでは紹介しきれないツールがたくさん存在します。

たとえばネットワーク系は「tcpなんとか」という形でまとまっているものもあります。tcpconnectやtcpacceptはそのままconnect()accept()を検知しますし,tcpconnlatでconnect()で時間がかかっているものを調べられます。tcplifeはTCPセッションの時間と送受信バイトを表示してくれます。セッションの状態遷移を表示してくれるtcpstatesなんてコマンドもあります。何ができるのかを把握するためにも,一通り試してみると良いでしょう。

$ sudo tcpstates-bpfcc
SKADDR           C-PID   C-COMM     LADDR           LPORT RADDR           RPORT OLDSTATE    -> NEWSTATE    MS
ffff8c62d94d2bc0 0       swapper/7  192.168.0.59    39242 162.213.33.6    443   ESTABLISHED -> CLOSE_WAIT  0.000
ffff8c62d94d2bc0 1711445 Socket Thr 192.168.0.59    39242 162.213.33.6    443   CLOSE_WAIT  -> LAST_ACK    0.086
ffff8c62d94d2bc0 56      ksoftirqd/ 192.168.0.59    39242 162.213.33.6    443   LAST_ACK    -> CLOSE       234.077

memleakやoomkill,deadlockなどは問題の解析に役立つはずです。また従来perfが行っていた機能としては,funccountやprofileなどが用意されています。さらにtraceコマンドは,snoop系のコマンドのようなことをより細かな制御で実行できます。

ほとんどのコマンドが--helpオプションによって,より詳細な説明や実践的な例を表示してくれます。まずは気になるコマンドを見つけて,実際に試してみると良いでしょう。

著者プロフィール

柴田充也(しばたみつや)

Ubuntu Japanese Team Member株式会社 創夢所属。数年前にLaunchpad上でStellariumの翻訳をしたことがきっかけで,Ubuntuの翻訳にも関わるようになりました。