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

カーネルを再構築することなくカーネルの動作を深く詳細に確認できると便利です。今回紹介するSystemTapを使うと、ちょっとしたスクリプト言語を書くだけで、カーネル上の特定の処理をフックし、必要な情報を収集・分析できます。

SystemTapがあるとうれしい理由

SystemTapは実行中のカーネルの処理をフックして、必要に応じて情報を収集し、出力するツールです。

カーネルのデバッグにおける代表的な手法と言えば「printk()の差し込み」です。printk()関連の関数を使えば多くの問題の状況を把握できますし、その情報がそのまま解決につながる例だってたくさんあります[1]⁠。

いわゆる「printk()デバッグ」は強力な手法ではあるものの、いくつかの弊害も存在します。

printk()を差し込むためにカーネルやモジュールをビルドし直さなくてはならない
環境に合わせたカーネルやモジュールのビルド方法を調べる必要がある
カーネルを作り直した場合は再起動が必要
自分でビルドしたカーネルやモジュールだと現象が発生しない
printk()を入れる適切な場所を探るために何度もカーネル・モジュールの再構築を繰り返す
printk()を入れると現象が発生しない
いろいろなところにprintk()を入れすぎた結果、本当に見たかったログが流れてしまう
ログをメモリに貯めて現象が起きたあとにダンプするようにしたら現象が発生しない
そんな感じでトライアンドエラーを繰り返したら、本来起きていた現象がコードを元に戻そうが何しようがまったく発生しなくなった

要するに「なんでもかんでもprintk()だけで調査しようとするな」という話ではあります。その「printk()以外の方法」のひとつが、今回紹介するSystemTapです。

SystemTapは「STPスクリプト」と呼ばれる独自言語のスクリプトを利用して記述します。SystemTapのコマンドであるstapコマンドがSTPスクリプトとカーネルのデバッグ情報から、C言語のコードを生成して、それをカーネルモジュールとしてビルド・ロードし、その結果を標準出力や独自のログバッファなどに保存するのです。

カーネル側で使用している要素技術は第443回でも紹介している「Livepatch」とほぼ同じです。むしろSystemTapはLivepatchよりもはるかに古くから存在する仕組みであり、Livepatchの先輩にあたる存在と言えるでしょう。

カーネルモジュールとして必要なコードをカーネルに挿入し、情報を取得します。よって第526回や第528回のようなカーネルそのものをビルドし再起動することは不要ですし、モジュールビルドする側のスペックもそこまで高いものは不要です。モジュールをアンロードすれば動作を停止しますし、出力をオンメモリのログバッファにしてしまえば、ログ出力による影響もある程度は抑えられます。

STPスクリプトのフォーマットを覚える必要はありますが、シンプルな書式なのでそこまで難しくはないでしょう。むしろカーネルデバッグをするのですから、Linuxカーネルに関する知識やそのコードを読み解く能力のほうが重要です。とは言え低レイヤーの話なので、数々のコンポーネントが複雑に絡み合う上位レイヤーに比べるとカーネルのコードは、はるかに「わかりやすい」です。

SystemTapに関してはRed Hatのドキュメントが充実しています。本記事を一通り読んでなんとなくUbuntuにおけるSystemTapの導入方法が掴めたら、「⁠SystemTapビギナーズガイド」や「SystemTapタップセットリファレンス」を読むと良いでしょう。

UbuntuにSystemTapをインストールする

Ubuntuで必要なのは「SystemTap本体」と「対象カーネルのデバッグ情報」のふたつです。これらに関してはUbuntuのWikiページに情報がまとまっています。言い方を変えるとこれらをインストールしてしまえば、SystemTapを利用できます[2]⁠。

さらにカーネルモジュールを自前でビルド・ロードするため、SecureBootもオフにしておくと良いでしょう。

まずはカーネルのデバッグ情報をインストールします。残念ながらデバッグ情報付きのカーネルは公式リポジトリには存在しません。おそらく用途が限定的であることと、公式ミラーリポジトリのサイズをあまり大きくしないようにするためでしょう。

よって公式のデバッグシンボル付きパッケージリポジトリを導入します。

$ sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys C8CAB6595FDFF622
$ codename=$(lsb_release -c | awk  '{print $2}')
$ sudo tee /etc/apt/sources.list.d/ddebs.list << EOF
deb http://ddebs.ubuntu.com/ ${codename}      main restricted universe multiverse
#deb http://ddebs.ubuntu.com/ ${codename}-security main restricted universe multiverse
deb http://ddebs.ubuntu.com/ ${codename}-updates  main restricted universe multiverse
deb http://ddebs.ubuntu.com/ ${codename}-proposed main restricted universe multiverse
EOF
$ sudo apt update

これでリポジトリの導入は完了です。ちなみにこのリポジトリではカーネル以外のデバッグ情報付きパッケージも提供しています。もし特定のパッケージのデバッグを行いたい際にも役に立つでしょう[3]⁠。

現在起動しているカーネルのデバッグシンボルパッケージをインストールしましょう。

$ sudo apt install -y linux-image-$(uname -r)-dbgsym

それなりのサイズなのでインストールに時間がかかるかもしれません。

インストールされたカーネルイメージやモジュールを確認してみましょう。「⁠with debug_info」の表示があるはずです。

$ file /usr/lib/debug/boot/vmlinux-5.0.0-25-generic
/usr/lib/debug/boot/vmlinux-5.0.0-25-generic:
  ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked,
  BuildID[sha1]=001ef6c2e051165f5d367f76cb69134d51080491,
  with debug_info, not stripped

$ file /usr/lib/debug/lib/modules/5.0.0-25-generic/kernel/fs/btrfs/btrfs.ko
/usr/lib/debug/lib/modules/5.0.0-25-generic/kernel/fs/btrfs/btrfs.ko:
  ELF 64-bit LSB relocatable, x86-64, version 1 (SYSV),
  BuildID[sha1]=b3045fb79f4d0bc72a24d9311f5e703ccfcc03fe,
  with debug_info, not stripped

それに対して通常のカーネルモジュールには「with debug_info」がありません。

$ file /usr/lib/modules/5.0.0-25-generic/kernel/fs/btrfs/btrfs.ko
/usr/lib/modules/5.0.0-25-generic/kernel/fs/btrfs/btrfs.ko:
  ELF 64-bit LSB relocatable, x86-64, version 1 (SYSV),
  BuildID[sha1]=b3045fb79f4d0bc72a24d9311f5e703ccfcc03fe,
  not stripped

これでデバッグ情報の準備は整いました。あとはSystemTap本体もインストールしておきます。

$ sudo apt install -y systemtap gcc

ちなみにsystemtap-docパッケージもインストールしておくと、膨大なマニュアル類もマシン上のmanコマンド経由で参照できます。使い方を学びたいなら、一緒にインストールしておくと良いでしょう。

Kernel 5.0以降の対応

Ubuntu 18.04 LTSのHWE用やUbuntu 19.04ではLinux Kenel 5.0が採用されています。しかしながらSystemTapはバージョン4.1以降でのみKernel 5.0に対応しており、Ubuntuのそれぞれのリリースのリポジトリで提供されているSystemTapのバージョンである3.1や4.0ではKernel 5.0に対応していません。

よってSystemtapを使おうとすると次のようにエラーとなります。

$ sudo stap -v -e 'probe vfs.read {printf("read performed\n"); exit()}'
Pass 1: parsed user script and 472 library scripts using 112688virt/88684res/7176shr/81800data kb, in 320usr/40sys/365real ms.
Pass 2: analyzed script: 2 probes, 1 function, 7 embeds, 0 globals using 350352virt/328168res/8868shr/319464data kb, in 4450usr/1590sys/7451real ms.
Pass 3: translated to C into "/tmp/stapAWAC1G/stap_420924b94a0c00e3cc489953451a803c_2994_src.c" using 350352virt/328304res/9004shr/319464data kb, in 10usr/0sys/8real ms.
cc1: fatal error: /tmp/stapAWAC1G/stapconf_4ff4fabb43cabe9eb683696051bfe0ac_726.h: そのようなファイルやディレクトリはありません
compilation terminated.
cc1: fatal error: /tmp/stapAWAC1G/stapconf_4ff4fabb43cabe9eb683696051bfe0ac_726.h: そのようなファイルやディレクトリはありません
compilation terminated.
make[1]: *** [scripts/Makefile.build:286: /tmp/stapAWAC1G/stap_420924b94a0c00e3cc489953451a803c_2994_aux_0.o] エラー 1
make[1]: *** 未完了のジョブを待っています....
make[1]: *** [scripts/Makefile.build:286: /tmp/stapAWAC1G/stap_420924b94a0c00e3cc489953451a803c_2994_src.o] エラー 1
make: *** [Makefile:1606: _module_/tmp/stapAWAC1G] エラー 2
WARNING: kbuild exited with status: 2
Pass 4: compiled C into "stap_420924b94a0c00e3cc489953451a803c_2994.ko" in 960usr/620sys/1533real ms.
Pass 4: compilation failed.  [man error::pass4]
Tip: /usr/share/doc/systemtap/README.Debian should help you get started.

もしKenrel 5.0以降のデバッグを行いたいならSystemTapの4.1以降をインストールしてください。ソースコードからビルドする方法が確実ではありますが、開発版19.10にある4.1パッケージをそのままコピーしたPPAも用意してあります。

PPA版のSystemTapは次の方法でインストールできます。

$ sudo add-apt-repository ppa:cosmos-door/systemtap
$ sudo apt install systemtap

これで19.10やUbuntu 18.04 LTSでKernel 5.0が動いている場合も、SystemTapを利用できるはずです。

プローブポイントのリストアップ

さて準備も整ったところでSystemTapを使ってみましょう。SystemTapの基本は「プローブポイントを指定し、そこで任意のコードを実行する」ことです。

プローブポイントとはカーネル内で処理をフックできる箇所です。代表的なのは関数が呼び出されたタイミングと関数を出ていくタイミングですが、他にもいろいろなプローブポイントの指定方法が存在します。

試しに特定の関数のプローブポイントをリストアップしてみましょう。たとえば次のコマンドは、カーネル内に存在する「acpi_」で始まる関数のうち、プローブポイントとして指定できる関数のリストと具体的なコードの場所です。

$ stap -l 'kernel.function("acpi_*")' | head
kernel.function("acpi_ac_add@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:331")
kernel.function("acpi_ac_battery_notify@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:293")
kernel.function("acpi_ac_get_state@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:128")
kernel.function("acpi_ac_notify@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:257")
kernel.function("acpi_ac_remove@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:415")
kernel.function("acpi_ac_resume@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/ac.c:392")
kernel.function("acpi_acquire_global_lock@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/acpica/evxface.c:1051")
kernel.function("acpi_acquire_mutex@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/acpica/utxfmutex.c:136")
kernel.function("acpi_add_id@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/scan.c:1172")
kernel.function("acpi_add_nondev_subnodes@/build/linux-hwVdeu/linux-4.15.0/drivers/acpi/property.c:148")

特定のカーネルモジュールすべての関数を表示したい場合は、次のように実行します。次の例だとbtrfsモジュールが対象です。

$ stap -l 'module("btrfs").function("*")' | head
module("btrfs").function("BTRFS_I@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/btrfs_inode.h:208")
module("btrfs").function("BTRFS_LEAF_DATA_SIZE@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/ctree.h:1351")
module("btrfs").function("BTRFS_MAX_INLINE_DATA_SIZE@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/ctree.h:1371")
module("btrfs").function("BTRFS_MAX_ITEM_SIZE@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/ctree.h:1359")
module("btrfs").function("BTRFS_MAX_XATTR_SIZE@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/ctree.h:1377")
module("btrfs").function("BTRFS_NODEPTRS_PER_BLOCK@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/ctree.h:1364")
module("btrfs").function("ClearPageChecked@/build/linux-H8RPB2/linux-5.0.0/include/linux/page-flags.h:296")
module("btrfs").function("ClearPageError@/build/linux-H8RPB2/linux-5.0.0/include/linux/page-flags.h:283")
module("btrfs").function("ClearPagePrivate2@/build/linux-H8RPB2/linux-5.0.0/include/linux/page-flags.h:318")
module("btrfs").function("ClearPagePrivate@/build/linux-H8RPB2/linux-5.0.0/include/linux/page-flags.h:316")

「-l」の代わりに「-L」を使うと、参照できる変数と型も表示してくれます。

$ stap -L 'module("btrfs").function("zstd_compress*")'
module("btrfs").function("zstd_compress_pages.cold.5")
module("btrfs").function("zstd_compress_pages@/build/linux-H8RPB2/linux-5.0.0/fs/btrfs/zstd.c:79")
  $ws:struct list_head* $mapping:struct address_space* $start:u64
  $pages:struct page** $out_pages:long unsigned int*
  $total_in:long unsigned int* $total_out:long unsigned int*
  $ret:int $params:ZSTD_parameters

システムコールもプローブポイントです。

$ sudo stap -l 'syscall.a*' | head
syscall.accept
syscall.accept4
syscall.access
syscall.acct
syscall.add_key
syscall.adjtimex
syscall.alarm
syscall.arch_prctl

仮想ファイルシステムの操作をトリガーにしたいのならvfsを使うと良いでしょう。

$ stap -l 'vfs.*' | head
vfs.__add_to_page_cache
vfs.__set_page_dirty_buffers
vfs.add_to_page_cache
vfs.buffer_migrate_page
vfs.do_mpage_readpage
vfs.do_sync_read
vfs.do_sync_write
vfs.open
vfs.read
vfs.readv

その他のプローブポイントについてはsystemtap-docパッケージ付属のstapprobesマニュアルを参照してください。

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

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

$ 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()」には（そこまで）頼ることなく、問題の要因を探る方法を紹介します。