bpftraceコマンドでダイナミック・トレーシングしてみよう！

新しいトレーシング用ツール

bpftraceは、Alastair Robertsonさんたちによって開発されているBPFのフロントエンドとして動作するトレーシング・ツールです。同じようなものとしては、BPF Compiler Collection (BCC)という高機能なツール群が既にあるのですが、bpftraceでは、付属する独自の言語を使って、その場に応じたトレーシングが簡単にできるように工夫されています。

こうしたツールは運用の現場で起きる突発的なパーフォーマンスの劣化やリソースの大量消費等のトラブルシューティングに使われることが多いため、「簡単に使える」ことは大切です。現場の担当者がプレッシャーに圧し潰されそうになりながら原因調査を行っている状況を想像してみてください。簡単に使えて、詳細なデータを採取できるツールがあれば、助かりますよね。

bpftraceはそんなツールです。本稿では、その有用性を理解してもらうために、仕組みよりも「使い方」に重点を置いて説明します。もし興味を持ったら、Brendan D. Greggさんのホームページで公開されている詳細な資料を見てください。

トレーシング・ツールとは

システムのパーフォーマンスやリソースに関連するコマンドは実にたくさんあります。まず、〜statというような名前のものがあります。すぐに思いつくものだけでも、mpstat, netstat, vmstat, iostat, dstatがありますね。他にもps, top, sarは良く知られています。

こうしたコマンドは、そのときの状態(State)や一定間隔毎の統計情報(Statistics)を表示することを目的としています。軽いので日常的な監視には最適です。しかし、問題が発見されても、これらのツールだけで、根本原因の特定に至るのは難しいと思います。

そこで必要となるのがトレーシング・ツールです。特定の観察対象を決めて、それに関わるデータを継続的に収集することを目的としたツールです。システムへの負荷が高くなる傾向があるため、日常の監視用には不向きですが、トラブルシューティングには必要不可欠なものです。

トレーシング・ツールとして一番有名なものは、tcpdumpコマンドでしょう。このコマンドはネットワークを流れるパケットを観察対象とすることができるため、ネットワーク関連のトラブルシューティングには大変役に立ちます。しかし、当たり前ですが、tcpdumpコマンド（より一般的には、パケット・フィルタリング・ツール）では、観察対象がパケットに限られています。それに対して、これから説明するbpftraceコマンドでは、様々なものを観察対象とすることができる点に特徴があります。

BPFとは

bpftraceコマンドは、その名前("bpf" + "trace")のとおり、BPFの仕組みを使ったトレーシング・ツールです。"trace"については既に説明したので、BPFについても説明しなければ片手落ちですが、ここでは詳細な説明はしません。bpftraceコマンドはツールなので、その仕組みが分からなくても使うことはできます。（もちろん、理解して使えば、より上手に使えるはずです。）

ここでは、差し当たって以下の２つを覚えておけば十分です。

1. bpftraceコマンドはカーネル側から提供されれるBPFという仕組みを使っている。
2. BPFは、主要な機能の実装は終わっているが、現在も改良が継続して行われている。

そのため、カーネルのバージョンが新しいほど、多くの機能が使えるようになっています。以下の例では、最近リリースされたFedora 29 (Kernel 4.19)を使用しています。

スタティック/ダイナミック　トレーシング

トレースする対象や箇所が予めバイナリに埋め込まれているトレーシングはスタティック・トレーシングと呼ばれます。先に挙げたtcpdumpコマンドはスタティック・トレーシングの一例です。より簡単なものでは、デバッグ用のprintf文もスタティック・トレーシングの例と言えるでしょう。

それに対して、対象や箇所を自分で決めて行うトレーシングをダイナミック・トレーシングと呼びます。サービスを開始した後にエラーが発生し、ログをベースに調査しているとき、「この関数が返すエラーコードがエラーログに出力されていればどれだけ助かっただろう！」と思ったことはありませんか。ダイナミック・トレーシングを使えば、こうしたケースにも対応可能になります。

bpftraceコマンドでは、トレースする箇所を指定するために以下の４つのキーワードが用意されています。

• kprobe, kretprobe: カーネル空間でのダイナミック・トレース用
• uprobe, uretprobe: ユーザ空間でのダイナミック・トレース用

ちなみにスタティック・トレース用に使われるキーワードはtracepointです。

bpftraceコマンドのインストール方法

使用しているOSがFedoraの場合、インストールは非常に単純です。この手順に従ってください。ディフォルトの設定では、bpftraceコマンドは/usr/local/binに、bpftraceコマンドをベースにしたツール群は/usr/local/share/bptrace/toolsにインストールされます。

練習用のサンプルコード

後半では、キーワードuprobeとuretprobeを使ってユーザ・プログラムを対象としたダイナミック・トレーシングの練習をします。以下がその練習に使うサンプルコードtracesample.cです。

tracesample.c

#include <stdio.h>
#include <string.h>

size_t getBufSize(const char *buf) {
    return strlen(buf);
}

int main(void)
{
    char buffer[256];
    size_t length;

    for (;;) {
        printf("Input: ");
        if (fgets(buffer, 256, stdin) == NULL || buffer[0] == '\n') {
            break;
        }
        length = getBufSize(buffer);
        printf("Length: %zu\n", length - 1);
    }
    return 0;
}

かなりわざとらしいのですが、後でuprobeとuretprobeの使い方を説明をするために、標準入力から入力された文字列の長さを測る処理を別立てのgetBufSize()という関数にしています。コンパイラは、gccでもclangでも構いません。DWARFデバッグ情報を付加する必要もありません。シンボルテーブルは必要なので、ストリップしないでください。

# gcc -o tracesample tracesample.c
# ./tracesample
# Input: aaaa
Length: 4

これで準備完了です。

uprobeを使った引数の確認

それでは、uprobeを使ってgetBufSize()関数に渡される引数の値を見てみましょう。引数の値は、arg0, arg1,...といったビルトイン変数に設定されているので、それをプリントするだけです。コンパイルを行ったディレクトリで、以下のようにbpftraceコマンドを起動してみてください。

$ sudo bpftrace -e 'uprobe:./tracesample:getBufSize { printf("geBufSize arg0: %s\n", str(arg0)); }'

ここで再度、tracesampleに適当な文字列を入力してください。それが上記にも出力されるようになっていることが分かります。

$ sudo bpftrace -e 'uprobe:./tracesample:getBufSize { printf("geBufSize arg0: %s\n", str(arg0));}'
Attaching 1 probe...
geBufSize arg0: aaaa

uretprobeを使った戻り値の確認

次は、uretprobeを使って、getBufSize()の戻り値を確認します。戻り値はビルトイン変数retvalに設定されているため、今度もその値をプリントするだけです。

$ sudo bpftrace -e 'uretprobe:./tracesample:getBufSize { printf("getBufSize returned: %d\n", retval); }'
Attaching 1 probe...
getBufSize returned: 5

簡単ですね！

ダイナミック・リンク・ライブラリのトレース

今度は、サンプル・プログラムがダイナミック・リンクしている関数をトレースしてみましょう。まず、どんな関数をダイナミック・リンクしているかを調べます。

$ objdump -T ./tracesample

./tracesample:     ファイル形式 elf64-x86-64

DYNAMIC SYMBOL TABLE:
0000000000000000      DF *UND*  0000000000000000  GLIBC_2.2.5 strlen
0000000000000000      DF *UND*  0000000000000000  GLIBC_2.2.5 printf
0000000000000000      DF *UND*  0000000000000000  GLIBC_2.2.5 __libc_start_main
0000000000000000      DF *UND*  0000000000000000  GLIBC_2.2.5 fgets
0000000000000000  w   D  *UND*  0000000000000000              __gmon_start__
0000000000404040 g    DO .bss   0000000000000008  GLIBC_2.2.5 stdin

GLIBCで定義されているfgets()が良さそうです。念のためlddコマンドを使ってライブラリの場所を確認しておきましょう。

$ ldd ./tracesample
        linux-vdso.so.1 (0x00007ffc3718b000)
        libc.so.6 => /lib64/libc.so.6 (0x00007fad00377000)
        /lib64/ld-linux-x86-64.so.2 (0x00007fad0055a000)

それでは、このダイナミック・リンク・ライブラリで定義されているfgets()関数をトレースしてみます。

$ sudo bpftrace -e 'uretprobe:/lib64/libc.so.6:fgets { printf("fgets: %s\n", str(retval));}'

何か、色々出て来ましたね。fgets()を使っているプログラムは他にもたくさんあるためです。そういうときは、commというビルトイン変数を使って対象を絞り込みます。この変数には、プロセス名が設定されています。

$ sudo bpftrace -e 'uretprobe:/lib64/libc.so.6:fgets / comm == "tracesample" / { printf("fgets: %s\n", str(retval));}'

これでtracesampleに対する入力のみが表示されるようになります。

uprobeとuretprobeを一緒に使う

uprobeとuretprobeを組み合わせて使えば、関数の処理にかかった時間を計ることができます。

$ sudo bpftrace -e 'uprobe:./tracesample:getBufSize { @start = nsecs; } uretprobe:./tracesample:getBufSize { printf("Latency: %d\n", nsecs -　@start );}'

nsecsというのが現時刻のタイムスタンプ（単位：ナノ秒）です。getBufSize()は、実際には、strlen()しかしていません^^;。すぐに終わってしまうため、良い例ではありませんが、使い方は分かっていただけると思います。

これを使えば、サーバのどの関数で時間がかかっているかを調査することができます。実際のサーバは、マルチプロセス/マルチスレッドで動作しているため、pid（プロセスID)やtid（スレッドID）といったビルトイン変数を使い、開始時刻と終了時刻を対応付けることが必要で、もう少し複雑になります。どうすれば良いかは、後ほど紹介するone-linerにあるRead時間の計測の例を参考にしてください。

興味を持ったなら

どうでしたでしょうか。bpftraceコマンドの可能性を実感していただけたでしょうか。もし興味を持たれたのであれば、このbpftraceを使ったone-linerを見てみることをお勧めします。ここまでで説明したことは、機能のごく一部にすぎませんが、ほとんどのone-linerはおおよそ理解できるようになっているはずです。

* このコマンドは、まだ開発中ということもあり、不安定な部分もあります。運用環境で使うのは、もうしばらくしてからの方が良いかもしれません。
* 本稿は、弊社内で開催したBPFとトレーシング・ツールに関する勉強会の内容を元に、そのとき行ったデモを中心に再構成したものです。