Ubuntu Weekly Recipe

第584回 SystemTapでカーネルの挙動を確認する

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

プローブポイントにトリガーをセットする

プローブポイントにトリガーをセットすることで,そのプローブポイントが呼ばれたら登録されているトリガーを呼び出します。

$ sudo stap -v -e 'probe vfs.read {printf("read performed\n"); exit()}'
Pass 1: parsed user script and 465 library scripts using 114324virt/49096res/6748shr/42648data kb, in 90usr/0sys/91real ms.
Pass 2: analyzed script: 1 probe, 1 function, 7 embeds, 0 globals using 340476virt/276868res/8240shr/268800data kb, in 2170usr/290sys/2714real ms.
Pass 3: translated to C into "/tmp/stap5wPauG/stap_2105033c25e89abb09691f212f5ebefc_2666_src.c" using 340476virt/277060res/8432shr/268800data kb, in 0usr/10sys/4real ms.
Pass 4: compiled C into "stap_2105033c25e89abb09691f212f5ebefc_2666.ko" in 7480usr/600sys/8287real ms.
Pass 5: starting run.
read performed
Pass 5: run completed in 20usr/0sys/323real ms.

stapコマンドはSTPファイル経由でのスクリプトの実行だけでなく,-eオプションを渡すことでコマンドラインに直接イベントを書けます。

上記の例では仮想ファイルシステムでのread()呼び出しが発生したら,その旨のメッセージを表示しprintf())⁠処理を終了しますexit())⁠たとえばexit()がないと,何か読み込みを行うたびにメッセージが表示され続けることになります。

-vオプションを付けると,上記のように「Pass…」のメッセージが表示されます。Pass 1でスクリプトをパースして,Pass 2でシンボル情報の解決を行い,Pass 3でそれらの情報をC言語のファイルに落とし込み,Pass 4でコンパイルし,Pass 5で作成したカーネルモジュールをロードします。各ステージの詳細はstapのマニュアルのPROCESSINGの項を参照してください。ちなみに-p 数字でそのPassで処理を止め,Passによっては生成物を表示します。どんなコードを生成しているか確認したいときに便利です。

結果を見るとすぐに「read performed」が表示されていることがわかりますね。これは誰かがread()を呼び出したためです。

より詳細なSTPスクリプトは,ファイルに記述することになります。たとえば以下のようなtest1.stpファイルを作成してみます。

#!/usr/bin/env stp

probe kernel.function("sys_read").call {
  printf("%s -> %s\n", thread_indent(1), probefunc())
  printf("%s args [%s]\n", probefunc(), $$parms)
  exit()
}

上記はsys_read()「呼び出された」ときに実行されるコードです。まずfonction(FOO).callのようにプローブポイントの後ろに.callと付けることで,⁠インラインでない関数の呼び出し」のみに限定されます。.inlineなら「インラインな関数のみ」⁠.exportedなら「エクスポートされている関数のみ」となります。今回の例だと.callのありなしで結果は変わりません。

%s -> %sの書式でプローブポイントとなる関数を表示しています。thread_indent()は現在のタスクを表示したあとに,呼び出しに応じてインデントするよう空白文字を差し込むヘルパー関数です。今回は1回呼び出されたらすぐに終了するのであまり意味はありません。probefunc()はプローブポイントの関数名です。このあたりの情報はman function::関数名などで詳しい情報を取得できます。

$$paramsはプローブポイントの引数を展開する変数です。つまり%s args [%s]関数名 args [引数リスト]となります。

実際に実行してみましょう。

$ sudo stap -v test1.stp
Pass 1: parsed user script and 465 library scripts using
  114320virt/49172res/6828shr/42644data kb, in 90usr/0sys/88real ms.
Pass 2: analyzed script: 1 probe, 18 functions, 5 embeds, 2 globals
  using 178440virt/114732res/8160shr/106764data kb, in 620usr/50sys/675real ms.
Pass 3: translated to C into "/tmp/stapfy7sof/stap_0bfb2743588f284e88bf9e11013b8d23_7991_src.c"
  using 178440virt/114976res/8352shr/106764data kb, in 90usr/0sys/105real ms.
Pass 4: compiled C into "stap_0bfb2743588f284e88bf9e11013b8d23_7991.ko"
  in 2850usr/220sys/3101real ms.
Pass 5: starting run.
     0 stapio(8415): -> SyS_read
SyS_read args [fd=0x4 buf=0x7ffc8de2eb40 count=0x2004]
Pass 5: run completed in 20usr/10sys/317real ms.

thread_indent()の結果として「stapio」が表示されていますが,これはstapコマンドから呼び出される子プロセスです。つまり自分自身のsys_read()を検知しているわけですね。

逆に関数から戻るときは.callの代わりに.returnと指定すればフックできます。

#!/usr/bin/env stp

probe kernel.function("sys_read").return {
  printf("exit %s <- %s\n", thread_indent(-1), probefunc())
  printf("%s args [%s]\n", probefunc(), $$return)
  exit()
}

$$return$$argsと同じように,今度は戻り値が格納されている変数となります。ちなみに.returnのプローブポイントは指定した関数が「戻ったあと」の場所にセットされます。上記の内容をtest2.stpとして保存して,今度は-vオプションなしで実行してみましょう。

$ sudo stap test2.stp
exit      0 stapio(20240): <- do_syscall_64
do_syscall_64 args [return=0xc]

stapioプロセスからのシステムコールとしてsys_read()が呼ばれ,その戻り値は0x12(正の値なので12バイトの読み込み)であることがわかります。

情報表示の例としては,他にもカーネル側のバックトレースを表示するprint_backtrace()や,現在のレジスタをダンプするprint_regs()なども存在します。詳細はman function::関数名でマニュアルを参照してください。

ここまで読んだかたなら,おおよそ想像がついていることでしょう。ええ,そうです。SystemTapを使ったデバッグでも,スクリプト作成者のスキル次第で結局printf()に頼ることになります。

そこで次回は,ネットワーク関連の具体的な事例を元にprintf()には(そこまで)頼ることなく,問題の要因を探る方法を紹介します。

著者プロフィール

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

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