bpftraceによるGoアプリケーションのトレース
はじめに
システムの状態を的確に捉え、運用に必要なインサイトを継続的に得るための特性は「オブザーバビリティ」と呼ばれます。オブザーバビリティを実現することで、パフォーマンスのモニタリングやトラブルシューティングを効果的に行い、システムの信頼性を高めることができます。
この重要な特性を実現する上で、eBPFやbpftraceは強力なツールとなります。
本記事では、Goアプリケーションにおけるオブザーバビリティを実現するための一つの方法として、bpftraceを用いたトレースの手法を紹介します。
内容が多いため、目次を活用して段階的に読み進めることをお勧めします。
eBPFとbpftrace
はじめに、eBPFとbpftraceについて簡単に説明します。
eBPFとは
eBPF(Extended Berkeley Packet Filter)はLinuxカーネル内で動作する柔軟なプログラミングフレームワークです。この技術を利用することで、開発者はカーネル空間内でネットワークモニタリング、セキュリティ、パフォーマンストラッキングなどのための小規模なプログラムを動的に実行できます。
これらのプログラムは、システムコールの実行や特定のトレースポイント、アプリケーションの任意の命令に到達した場合など、特定のイベントや条件に基づいてトリガーされ、リアルタイムでシステムの挙動を変更したり観察することが可能になります。
eBPFプログラムは、安全性を保証するため、カーネルにロードされる前に厳格に検証されます。このプロセスにより、メモリアクセス違反や無限ループなど、システムの安定性やセキュリティを脅かす可能性のある問題を事前に排除します。検証済みのプログラムはカーネル制御下でカーネルのメモリや重要なリソースに無制限にアクセスすることを防ぎつつ、高パフォーマンスで実行されます。
eBPFの強力な点はその拡張性にあります。開発者はカーネルの動作に影響を与えるプログラムを作成し、システムのあらゆる側面を監視および調整できます。例えば、ネットワークパケットのルーティングやフィルタリングのカスタマイズ、特定のシステムコールの監視、またはカーネル関数へのフックを設定して動作を変更できます。これにより、高度な最適化やデータの収集が可能になります。
eBPF Applications LandscapeではeBPFを使用したプロダクトが紹介されています。
bpftraceとは
bpftraceはeBPFのフロントエンドの一つです。eBPFの強力な機能を活用しながらもその複雑性を避け、高レベルのトレースを実践できるコマンドラインツールです。
awkに近い構文のDSLでeBPFプログラムを簡潔に書くことができるよう設計され、複雑なコンパイルやリンクのプロセスなしに、直接コマンドラインからeBPFプログラムを実行できます。
以下はbashのプロンプトに入力された文字列を出力するスクリプトの例です。
bpftrace -e 'uretprobe:/bin/bash:readline { print(str(retval)); }'bpftraceは多くのプローブタイプをサポートしており、さまざまなイベントにeBPFプログラムをアタッチ可能です。
bpftraceプロジェクトには日本語チュートリアルが用意されています。bpftraceの主要なポイントを習得できるので、ぜひ参考にしてください。
トレースを実践する
それでは早速bpftraceを使ってGoアプリケーションをトレースしてみましょう。
このセクションでは、Goアプリケーションの関数の実行、引数、戻り値をトレースする方法を紹介します。
実行環境
今回のガイドに用いた実行環境は以下のとおりです。筆者の環境では、limaを使用してmacOS上にUbuntu 22.04.4 LTSの仮想マシンを構築しました。
lima バージョン 0.21.0
アーキテクチャ: x86_64(amd64)
VMタイプ: qemu
Ubuntu 22.04.4 LTS
カーネルバージョン: 5.15.0-100-generic
go1.22.1
Ubuntu公式のパッケージでもbpftraceが提供されているのですが一部機能が制限されています。そのため、今回のガイドでは全ての機能を活用できるAppImage版を使用しました。
AppImageはアプリケーションバイナリを含む単一のファイルのため、インストールが簡単です。ダウンロードしたファイルに実行権限を付与するだけで利用できます。また、AppImageはシステムに依存しないため、他のLinuxディストリビューションでも利用できます。
AppImage版のインストールに関する詳細はbpftraceのインストールドキュメントを参照してください。
アプリケーションの準備
トレース対象となるアプリケーションのソースコードを以下に示します。フィボナッチ数を求めるmain.Fib関数を定義しており、今回のガイドでは主にこちらの関数がトレースの対象となります。
package main
import (
"flag"
"fmt"
)
func fib(n uint) uint {
if n < 2 {
return n
}
return fib(n-1) + fib(n-2)
}
func Fib(n uint) uint {
return fib(n)
}
func main() {
n := flag.Uint("n", 10, "The Fibonacci number to calculate")
flag.Parse()
fmt.Println(*n, "=>", Fib(*n))
}このガイドではmain.Fib関数をトレースするために、インライン展開を無効化してアプリケーションをビルドすることが必要です。さらに、デバッガーやトレーサーがソースコードと密接に関連した情報を提供できるように、最適化も無効にします。
以下に示すビルドフラグを用いることで、インライン展開を無効化し、デバッグ情報や関数のシンボルを削除せずにアプリケーションをビルドできます。デバッグ情報や関数のシンボルシンボルも必要となるので、-ldflagsフラグで-w(DWARFを削除する)や-s(シンボルテーブルを削除する)を指定しないように注意してください。
go build -gcflags "-l -N" -o appビルドされたアプリケーションのファイル形式を確認します。"with debug_info", "not stripped"と表示されていれば、デバッグ情報や関数のシンボルが含まれていることを意味します。
$ file ./app
./app: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), statically linked, Go BuildID=-u3_6H29R80UnICgWQj_/l4chn68HJS38y0cHnhGl/Mum4l3iNY5NZL5rtEGGt/dpURkZ3TYmL8h06bgnql, with debug_info, not stripped最後にbpftraceによるmain.Fib関数のトレース可否を確認するために、`bpftrace -l`コマンドを実行します。
$ sudo bpftrace -l '*:./app:main.Fib'
uprobe:./app:main.Fibコマンドの実行結果が何も表示されない場合は、関数がインライン化されている可能性があります。インライン化を無効化しているか、関数のシンボルを削除していないかを再度確認してください。
関数の実行をトレースする
さっそくbpftraceスクリプトを作成し、関数の実行をトレースしてみましょう。
関数シンボルmain.Fibに対してuprobeをアタッチすることで、その実行をトレースします。uprobeはアタッチした関数が実行される際に指定されたeBPFプログラムを実行します。
以下のスクリプトはmain.Fibが実行されるたびに実行時刻とプロセスIDを表示します。このスクリプトをtrace.btという名前のファイルに保存してください。
BEGIN {
printf("%-32s%-10s\n", "TIMESTAMP", "PID");
}
uprobe:./app:main.Fib {
printf(
"%-32s%-10d\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", nsecs),
pid
);
}作成したbpftraceスクリプトを実行します。
sudo bpftrace trace.bt 別ターミナルでビルドしたアプリケーションを実行します。何度か実行してみましょう。
$ ./app
10 => 55bpftraceを実行したターミナルにトレース結果が出力されます。トレース結果から、main.Fibの実行時刻とプロセスIDが表示されていることが確認できました。
ひととおり確認したらCtrl+Cで終了してください。
$ sudo bpftrace trace.bt
Attaching 2 probes...
TIMESTAMP PID
2024-03-17T12:27:57.962658+0900 18437
2024-03-17T12:32:43.877558+0900 18671
2024-03-17T12:32:43.986166+0900 18676
^Cプログラムを変更することなく、bpftraceを利用してmain.Fibの実行をトレースできることを確認できました。
関数の引数をトレースする
>= go1.17では関数の引数や戻り値はレジスタ経由で渡されます。この変更により、アプリケーションのパフォーマンスやバイナリサイズが改善されています。
また、トレースにおいては、以前はスタックから取得していた引数や戻り値をレジスタから読み取ることが可能になりました。これにより、アクセス速度の向上やシンプルなデータ取得、操作対象の明確化など、トレースの効率が向上するという利点があります。
以下のドキュメントを参照してこのトピックについて理解を深めることができます。Goの引数の扱いに関する基本的な情報だけでなく、トレースの際の具体的な戦略を立てる上で役に立ちます。
関数の引数や戻り値がレジスタ経由で渡されるようになったことによる効果と影響について説明しています。この変更はトレースの際のデータアクセス方法に影響を与えます。
Proposal: Register-based Go calling convention では、レジスタベースのABIの提案について詳細に説明しています
Goコンパイラが関数呼び出しの引数と結果の受け渡しをどのように扱うかについての詳細な仕様が記載されています。このドキュメントはGoアプリケーションのトレースにおいて、どのレジスタが重要であるかを理解する上で欠かせません。
amd64アーキテクチャに関するセクションでは、amd64アーキテクチャにおいて関数の引数にどのレジスタ使用するかについてのガイドラインを提供しています。これは関数の引数や戻り値をトレースする際の基礎知識となります。
Go のレジスタベース ABI はいくつまで引数をサポートしているのか？ #Go - Qiita
レジスタベースの引数の受け渡しについて、より実践的な内容を提供しています。とても参考になります。
ABIの仕様から、関数のprobe時にレジスタを参照することで引数の値を取得できます。
bpftraceではreg関数を使用してレジスタの値を取得できます。
trace.btを以下のように修正し、main.Fibの第1引数(amd64アーキテクチャでは第1引数はRAXレジスタに格納される)をトレースします。
BEGIN {
printf("%-32s%-10s%-10s\n", "TIMESTAMP", "PID", "ARG1");
}
uprobe:./app:main.Fib {
printf(
"%-32s%-10d%-10u\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", nsecs),
pid,
reg("ax")
);
}トレースを実行しつつ、main.Fibが1から10までの引数を取るようにアプリケーションを実行します。
$ for i in `seq 1 10`; do ./app -n $i; done
1 => 1
2 => 1
3 => 2
4 => 3
5 => 5
6 => 8
7 => 13
8 => 21
9 => 34
10 => 55トレース結果としてARG1に1から10まで順番に出力されれば成功です。
$ sudo bpftrace trace.bt
Attaching 2 probes...
TIMESTAMP PID ARG1
2024-03-17T19:06:08.676639+0900 29023 1
2024-03-17T19:06:08.826567+0900 29029 2
2024-03-17T19:06:08.930441+0900 29034 3
2024-03-17T19:06:09.070859+0900 29040 4
2024-03-17T19:06:09.226016+0900 29046 5
2024-03-17T19:06:09.325671+0900 29053 6
2024-03-17T19:06:09.424143+0900 29059 7
2024-03-17T19:06:09.554581+0900 29064 8
2024-03-17T19:06:09.650605+0900 29069 9
2024-03-17T19:06:09.798176+0900 29074 10
^Cレジスタからmain.Fibの引数を取得できることが確認できました。
main.Fibでは第1引数がuint型のためreg("ax")で値を取得できます。しかし、stringやslice, interfaceなど、複数のレジスタを使用するデータ型もあります。
たとえばamd64アーキテクチャ、go1.22.1でビルドしたアプリケーションの関数の第1引数がstring型である場合は、以下のようにしてその値を取得する必要があります。
// RAXにはデータが格納されているbyte配列のポインタ、RBXにはbyte数が渡される
$arg1 = str(reg("ax"), reg("bx"));これらのデータ型を扱う場合はGo internal ABI specificationのMemory Layoutセクションを参照し、それぞれのデータ型のメモリレイアウトと異なるアーキテクチャで使用されるレジスタの違いを確認することをおすすめします。
関数の戻り値をトレースする
関数の戻り値を調査するには関数シンボルに対してuretprobeをアタッチします。uretprobeはアタッチした関数がリターンする際に指定されたeBPFプログラムを実行します。
関数の引数をトレースするで述べたように、>= go1.17では関数の引数、戻り値はレジスタ経由で渡されます。引数を取得したときと同様にレジスタから戻り値を取得できます。
以下はmain.Fibが終了する際に、その戻り値を表示するbpftraceスクリプトです。
uretprobe:./app:main.Fib {
printf("%lu\n", reg("ax")); //戻り値をRAXレジスタから取得して表示する
}また、uprobeとuretprobeを組み合わせることで、関数の実行時間を効果的にトレースできます。uprobeを使用して関数開始時の情報を記録し、uretprobeでその記録された情報を参照して実行時間を計算します。
最終的に、実行時刻、プロセスID、レイテンシ（関数の実行開始から終了までの時間）、引数の値、および戻り値を表示するコードは以下のようになります。
BEGIN {
printf("%-32s%-10s%-12s%-10s%-10s\n", "TIMESTAMP", "PID", "LATENCY", "ARG1", "RET1");
}
uprobe:./app:main.Fib {
@start = nsecs; // 現在時刻を@startマップに記録する
@arg1 = reg("ax"); // 引数をRAXレジスタから取得し、@arg1マップに記録する
}
uretprobe:./app:main.Fib {
printf(
"%-32s%-10d%-12ld%-10u%-10lu\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", @start),
pid,
(nsecs - @start) / 1000, // @startマップから関数の開始時刻を取得し、実行時間(usec)を計算する,
@arg1, // @arg1マップから引数を取得する
reg("ax") // 戻り値をRAXレジスタから取得する
);
delete(@start);
delete(@arg1);
}trace.btを変更してトレースを実行し、再度main.Fibが1から10までの引数を取るようにアプリケーションを実行します。
for i in `seq 1 10`; do ./app -n $i; doneトレース結果として、それぞれの実行のLATENCY, ARG1, RET1が出力されれば成功です。
$ sudo bpftrace trace.bt
Attaching 3 probes...
TIMESTAMP PID LATENCY ARG1 RET1
2024-03-17T23:41:19.979961+0900 32690 171 1 1
2024-03-17T23:41:20.099992+0900 32695 168 2 1
2024-03-17T23:41:20.220726+0900 32701 182 3 2
2024-03-17T23:41:20.392182+0900 32707 176 4 3
2024-03-17T23:41:20.514469+0900 32713 169 5 5
2024-03-17T23:41:20.671847+0900 32719 196 6 8
2024-03-17T23:41:20.804982+0900 32725 359 7 13
2024-03-17T23:41:20.910254+0900 32730 167 8 21
2024-03-17T23:41:21.059410+0900 32736 166 9 34
2024-03-17T23:41:21.229957+0900 32742 177 10 55
^Cトレース結果から、main.Fibの戻り値をレジスタから取得できていることが確認できます。また、uprobeでmain.Fibの開始時刻や引数を記録し、uretprobeでそれらを取得して出力できることも確認できました。
uprobe/uretprobeのしくみ
ここまででuprobeとuretprobeを使用してGoアプリケーションの関数の実行、引数、戻り値をトレースする方法を紹介しました。
uprobeとuretprobeはプログラムの命令実行や関数のリターンのタイミングにeBPFプログラムを実行するための機能です。
それぞれのしくみについて説明します。
uprobeのしくみ
uprobeはユーザープログラム内の特定のアドレスにトレースポイントを設定する機能を提供します。main.Fib関数にuprobeをアタッチする場合、実際はmain.Fibシンボルが示す関数の先頭アドレスに対してトレースポイントを設定します。
uprobeをアタッチすると、指定されたアドレスの命令がブレークポイント命令(x86_64アーキテクチャではint3)に置き換えられます。ブレークポイント命令が実行されると特定のコード位置にプログラムの実行が到達したことを通知するSIGTRAPシグナルが生成されます。
このシグナルによって、カーネルは関連付けられたeBPFプログラムを呼び出します。eBPFプログラムの実行が完了すると、元の命令に戻して関数の実行が続行されます。
以下はuprobeアタッチ前のアセンブリです。
(gdb) disas main.Fib
Dump of assembler code for function main.Fib:
0x000000000048c500 <+0>: cmp 0x10(%r14),%rsp
0x000000000048c504 <+4>: jbe 0x48c535 <main.Fib+53>
0x000000000048c506 <+6>: push %rbp
...以下はuprobeアタッチ後のアセンブリです。main.Fibの先頭アドレスである0x000000000048c500がint3命令に置き換わっていることが確認できます。
この変更により、main.Fibが実行されるとeBPFプログラムが呼び出されます。
(gdb) disas main.Fib
Dump of assembler code for function main.Fib:
0x000000000048c500 <+0>: int3
0x000000000048c501 <+1>: cmp 0x10(%rsi),%esp
0x000000000048c504 <+4>: jbe 0x48c535 <main.Fib+53>
0x000000000048c506 <+6>: push %rbp
...uretprobeのしくみ
uretprobeは関数がリターンする際に、eBPFプログラムを実行するためのメカニズムです。
カーネルはuretprobeがアタッチされた関数が呼び出された際、その関数のリターン先のアドレスをeBPFプログラムのハンドラのアドレスに置き換えます。これにより、関数のリターン時にeBPFプログラムが実行されるようになります。
以下はuretprobeアタッチ前のmain.Fibのバックトレースです。0x000000000048c5ba(main.main)にリターンすることが確認できます。
(gdb) bt
#0 0x000000000048c534 in main.Fib (n=4769210, ~r0=10) at /Users/hayajo/Desktop/bpftrace-go/fib/main.go:16
#1 0x000000000048c5ba in main.main () at /Users/hayajo/Desktop/bpftrace-go/fib/main.go:23そしてuretprobeアタッチ後のバックトレースです。main.Fibのリターンアドレスが0x000000000048c5ba(main.main)から0x00000000f7ffd000に置き換わっていることが確認できます。
(gdb) bt
#0 0x000000000048c534 in main.Fib (n=4160737280, ~r0=10) at /Users/hayajo/Desktop/bpftrace-go/fib/main.go:16
#1 0x00000000f7ffd000 in ?? ()
#2 0x000000000000000a in ?? ()
...この置き換えにより、関数のリターン時にeBPFプログラムが実行され、関数の戻り値やその他のデータをトレースすることが可能になります。
Goアプリケーションのトレースにおける課題
uprobe, uretprobeをアタッチすることで、Goアプリケーションの関数の実行、引数、戻り値をトレースできました。
しかし、Goのランタイムの特徴による以下の課題があります。
ゴルーチンの識別
スタックの拡張
それぞれの課題とその解決策について説明します。
ゴルーチンの識別
ゴルーチンはGoのランタイムで管理される軽量なスレッドであり、ランタイムによってOSのスレッドにマッピングされます。ゴルーチンがI/O待ちやスリープ状態になると、OSスレッドは別のゴルーチンを実行します。
ゴルーチンが実行されるスレッドはGoランタイムによって自動的に切り替えられるため、OSスレッドのトレースだけではゴルーチンの実行状態を正確に把握できません。
これまでのサンプルアプリケーションのmain.Fibは1つのゴルーチンだけで実行されていたため、uprobe, uretprobe間の実行時刻や引数の値のやりとりは問題ありませんでした。しかし、複数のゴルーチンがmain.Fibを実行するようになると、情報のやりとりが正しく行われなくなります。
ゴルーチンによる並行処理の動作を確認するため、サンプルアプリケーションを以下のように変更します。
この変更により、-mフラグを指定することでnをインクリメントしながらmain.Fibをm回実行します。m > 1の場合は複数のゴルーチンでmain.Fibが実行されます。
package main
import (
"flag"
"fmt"
"sync"
)
func fib(n int) int {
if n < 2 {
return n
}
return fib(n-1) + fib(n-2)
}
func Fib(n int) int {
return fib(n)
}
func main() {
n := flag.Int("n", 10, "The Fibonacci number to calculate")
m := flag.Int("m", 1, "Number of iterations from 'n'")
flag.Parse()
var wg sync.WaitGroup
for i := range *m {
wg.Add(1)
go func() {
defer wg.Done()
v := *n + i
fmt.Println(v, "=>", Fib(v))
}()
}
wg.Wait()
}アプリケーションを再度ビルドし、-nフラグと-mフラグを指定してnを1から10まで変化させながら実行します。main.Fibが複数のゴルーチンにより並行に実行されるため、結果が順不同で出力されていることが確認できます。
$ go build -gcflags="-N -l" -o app
$ ./app -n 1 -m 10
3 => 2
8 => 21
10 => 55
4 => 3
1 => 1
2 => 1
6 => 8
7 => 13
5 => 5
9 => 34このアプリケーションに対して、ここまでの手順で作成したbpftraceスクリプトを実行した結果は以下の通りです。ARG1とRET1がマッチしない、奇妙な結果が示されています。
$ sudo bpftrace trace.bt
Attaching 3 probes...
TIMESTAMP PID LATENCY ARG1 RET1
2024-03-17T10:44:51.243584+0900 44641 2688 4 1
2024-03-17T10:44:51.243584+0900 44641 2696 4 8
2024-03-17T10:44:51.243584+0900 44641 2690 4 3
2024-03-17T10:44:51.243584+0900 44641 2700 4 55
2024-03-17T10:44:51.248760+0900 44641 48 1 1
2024-03-17T10:44:51.248883+0900 44641 41 5 5
2024-03-17T10:44:51.248945+0900 44641 36 8 21
2024-03-17T10:44:51.249005+0900 44641 30 7 13
2024-03-17T10:44:51.249055+0900 44641 27 3 2
2024-03-17T10:44:51.249088+0900 44641 27 9 34
^Cuprobeで記録しているmain.Fibの開始時刻や引数は、別のゴルーチンでの実行によって上書きされてしまいます。そのため、uretprobeでは別のゴルーチンの値を取得する可能性があり、正しい結果が得られません。
ゴルーチンの識別の解決策
この課題を解決するには、開始時刻や引数などの情報をゴルーチンごとに個別に記録する必要があります。
bpftraceでは組み込み変数のpid, tidを使用してアタッチした命令のプロセスID、スレッドIDを取得できますが、ゴルーチンの情報を取得する機能は提供されていません。
ゴルーチンの情報を取得するためには、Goランタイムによるゴルーチンのスケジューリングをトレースする必要があります。
runtime.schedule関数はゴルーチンがOSスレッドにスケジュールされる際に呼び出されます。
runtime.scheduleでは最終的にruntime.execute関数を呼び出し、ゴルーチンを実行します。
runtime.executeの引数には実行されるゴルーチンの情報を格納するruntime.g構造体のポインタが渡されます。このポインタを使用して、ゴルーチンの情報を取得できます。
runtime.g構造体の定義を確認すると、ゴルーチンID(goid)が格納されているフィールドがあることがわかります。
runtime.execute関数にuprobeをアタッチし、ゴルーチンIDを取得するコードは以下のようになります。
// runtime.g構造体の定義
// https://github.com/golang/go/blob/go1.22.1/src/runtime/runtime2.go#L422-L530
// Goのバージョンによって変更される可能性があります
struct g {
uint8_t padding[152]; // goidフィールドまでのパディング。pahole(1)やreflect, unsafeパッケージを利用してgoidのオフセットを確認できます。
int64_t goid; // ゴルーチンIDが格納されるフィールド
}
uprobe:./app:runtime.execute {
$g = (struct g *)(reg("ax")); // runtime.execute関数の第1引数からruntime.g構造体を取得します
printf("Goroutine ID: %d\n", $g->goid); // runtime.g構造体からゴルーチンIDを取得して表示します
}なお、runtime.g構造体のレイアウトやゴルーチンのスケジューリングはGoのバージョンによって変更される可能性があります。また、非公開のAPIや内部データにアクセスすることは将来のバージョンで動作しなくなる可能性があるため注意が必要です。
ゴルーチンIDをキーとして関数の実行開始時刻やその他の関連データを記録することで、特定のゴルーチンの実行をトレースすることが可能になります。
このアプローチで修正したtrace.btは以下の通りです。
struct g {
uint8_t padding[152];
int64_t goid;
}
BEGIN {
printf("%-32s%-10s%-12s%-10s%-10s\n", "TIMESTAMP", "PID", "LATENCY", "ARG1", "RET1");
}
// OSスレッドにスケジュールされたゴルーチンの実行をトレースします
uprobe:./app:runtime.execute {
$g = (struct g *)(reg("ax"));
@g[pid, tid] = $g->goid; // @gマップに現在のスレッドで実行されるゴルーチンID(goid)を記録します
}
uprobe:./app:main.Fib /@g[pid, tid]/ { // @gマップにgoidが記録されていることをチェックしてprobeをアタッチします
$goid = @g[pid, tid]; // @gマップから現在のスレッドで実行されているゴルーチンIDを取得します
@start[pid, $goid] = nsecs; // @startマップにプロセスID, ゴルーチンIDをキーとして開始時刻を記録します
@arg1[pid, $goid] = reg("ax"); // @arg1マップにプロセスID, ゴルーチンIDをキーとして引数を記録します
}
uretprobe:./app:main.Fib /@g[pid, tid]/ {
$now = nsecs;
$ret1 = reg("ax");
$goid = @g[pid, tid]; // @gマップからプロセスID, スレッドIDをキーとしてゴルーチンIDを取得します
$start = @start[pid, $goid]; // @startマップからプロセスID, ゴルーチンIDをキーとして開始時刻を取得します
$latency = ($now - $start) / 1000; // 関数の実行時間(usec)を計算します
$arg1 = @arg1[pid, $goid]; // @arg1マップからゴルーチンIDをキーとして引数を取得します
printf(
"%-32s%-10d%-12ld%-10u%-10lu\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", $now),
pid,
$latency,
$arg1,
$ret1
);
delete(@start[pid, $goid]); // @startマップから開始時刻の記録を削除します
delete(@arg1[pid, $goid]); // @arg1マップから引数の記録を削除します
}
END {
clear(@g); // ゴルーチンの情報を削除します
}上記のスクリプトで再度トレースを実行すると、正しい結果が出力されることを確認できます。
$ sudo bpftrace trace.bt
Attaching 5 probes...
TIMESTAMP PID LATENCY Argument Return
2024-03-17T11:08:55.279782+0900 45365 757 5 5
2024-03-17T11:08:55.279784+0900 45365 733 10 55
2024-03-17T11:08:55.279933+0900 45365 808 7 13
2024-03-17T11:08:55.279793+0900 45365 782 8 21
2024-03-17T11:08:55.281661+0900 45365 32 9 34
2024-03-17T11:08:55.282274+0900 45365 36 1 1
2024-03-17T11:08:55.282326+0900 45365 31 6 8
2024-03-17T11:08:55.282430+0900 45365 40 2 1
2024-03-17T11:08:55.282458+0900 45365 30 3 2
2024-03-17T11:08:55.282538+0900 45365 25 4 3
^Cこのようなアプローチにより、ゴルーチン単位で情報を記録することが可能となります。
スタックの拡張
ゴルーチンのスタックスペースが不足すると、Goのランタイムは新しいスタックを割り当てて古いスタックをコピーすることでスタックを拡張します。
main.Fibのアセンブリでもスタック拡張の命令が確認できます。runtime.morestack_noctxt.abi0がスタックの拡張を行う関数で、最終的にruntime.newstackが呼び出されて新しいスタックが割り当てられます。
$ objdump --disassemble=main.Fib ./app
...
000000000048c740 <main.Fib>:
48c740: 49 3b 66 10 cmp 0x10(%r14),%rsp
48c744: 76 2f jbe 48c775 <main.Fib+0x35>
...
48c775: 48 89 44 24 08 mov %rax,0x8(%rsp)
48c77a: e8 01 4e fd ff call 461580 <runtime.morestack_noctxt.abi0>
...uretprobeのしくみで解説したように、uretprobeをアタッチした関数はそのリターンアドレスがeBPFプログラムのハンドラを指すよう置き換えられます。
アタッチした関数内でスタックの拡張を行う関数が呼び出されると、置き換えられた命令が不正なリターンアドレスとして検知され、panicが発生します。
トレースを実行した状態で-nフラグに大きな値に設定してアプリケーションを実行すると、panicが発生して不正なリターンアドレスとして検知されることが確認できます。
$ ./app -n 30
...
runtime: g 38: unexpected return pc for main.Fib called from 0x7fffffffe000
stack: frame={sp:0xc00007beb8, fp:0xc00007bee0} stack=[0xc00007b000,0xc00007c000)
0x000000c00007bdb8: 0x000000c00007bde8 0x000000000048c6fb <main.fib+0x000000000000003b>
0x000000c00007bdc8: 0x0000000000000018 0x0000000000000000
0x000000c00007bdd8: 0x0000000000000000 0x000000000000000014 => 377
...
fatal error: unknown caller pc
...スタックの拡張の解決策
これに対する解決策として、uretprobeではなくuprobeを使用して関数のret命令にアタッチする方法があります。
uprobeによるプログラムのアタッチは関数シンボルだけでなくオフセット指定が可能です。これを利用して関数のret命令にuprobeアタッチします。
なお、オフセット指定を使用する場合はbpftraceがBFDをサポートしたビルドである必要があります。`bpftrace —info`コマンドを実行してBuildセクションに"bfd: yes"の記述があればBFDをサポートしたビルドです。Debian/UbuntuのbpftraceパッケージはBFDをサポートしたビルドではない可能性があります。その場合は自前ビルドやAppImage版の利用を検討してください。
$ sudo bpftrace --info
...
Build
version: v0.20.1
LLVM: 17.0.6
unsafe probe: no
bfd: yes
libdw (DWARF support): yes
...最終的なbpftraceスクリプト
最終的なtrace.btは以下のようになります。ゴルーチンやスタックの拡張に対応したbpftraceスクリプトとなっています。
注: go1.22.1でビルドしたアプリケーションに対する動作を確認しています。Goのバージョンによっては動作しない可能性があります。
struct g {
uint8_t padding[152];
int64_t goid;
}
BEGIN {
printf("%-32s%-10s%-12s%-10s%-10s\n", "TIMESTAMP", "PID", "LATENCY", "ARG1", "RET1");
}
uprobe:./app:runtime.execute {
$g = (struct g *)(reg("ax"));
@g[pid, tid] = $g->goid;
}
uprobe:./app:main.Fib /@g[pid, tid]/ {
$goid = @g[pid, tid];
@start[pid, $goid] = nsecs;
@arg1[pid, $goid] = reg("ax");
}
uprobe:./app:"main.Fib"+52 /@g[pid, tid]/ {
$now = nsecs;
$ret1 = reg("ax");
$goid = @g[pid, tid];
$start = @start[pid, $goid];
$latency = ($now - $start) / 1000;
$arg1 = @arg1[pid, $goid];
printf(
"%-32s%-10d%-12ld%-10u%-10lu\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", $now),
pid,
$latency,
$arg1,
$ret1
);
delete(@start[pid, $goid]);
delete(@arg1[pid, $goid]);
}
END {
clear(@g);
}HTTPリクエスト・レスポンスのトレース
もう少し実践的な例として、bpftraceによるGoのウェブアプリケーションに対するHTTPリクエスト・レスポンスのトレースのアプローチを紹介します。
注: go1.22.1でビルドしたアプリケーションに対する動作を確認しています。Goのバージョンによっては動作しない可能性があります。
サンプルアプリケーション
対象のサンプルアプリケーションは、/fib/{n}エンドポイントに対してGETリクエストを受け付け、main.Fib(n)を実行してその結果を返すウェブアプリケーションです。
package main
import (
"fmt"
"log"
"net/http"
"strconv"
)
const (
addr = ":8080"
)
func fib(n uint) uint {
if n < 2 {
return n
}
return fib(n-1) + fib(n-2)
}
func Fib(n uint) uint {
return fib(n)
}
func main() {
http.HandleFunc("GET /{$}", func(w http.ResponseWriter, r *http.Request) {
http.Redirect(w, r, "/fib/10", http.StatusFound)
})
http.HandleFunc("GET /fib/{n}", func(w http.ResponseWriter, r *http.Request) {
n, err := strconv.ParseUint(r.PathValue("n"), 10, 64)
if err != nil {
w.WriteHeader(http.StatusBadRequest)
return
}
v := Fib(uint(n))
if _, err := fmt.Fprintln(w, n, "=>", v); err != nil {
w.WriteHeader(http.StatusInternalServerError)
}
})
log.Printf("Starting http server on %+v", addr)
err := http.ListenAndServe(addr, nil)
if err != nil && err != http.ErrServerClosed {
log.Fatal("Failed to run http server", err)
}
}アプリケーションをビルドして実行します。
$ go build -gcflags="-N -l" -o app
$ ./app &
Starting http server on 8080/fib/{n}エンドポイントに対してGETリクエストを送信すると、main.Fib(n)の結果が返されることが確認できます。
$ curl localhost:8080/fib/10
10 => 55トレース範囲の決定
HTTPリクエスト・レスポンスのトレースを行うために、トレース範囲を決定します。
まずはbpftraceのustack関数を使って、main.Fibのスタックトレースを確認します。
BEGIN {
printf("Start tracing.\n");
}
uprobe:./app:main.Fib {
print(ustack());
}トレースを実行し、再度/fib/{n}エンドポイントにリクエストを送信します。以下のような結果が出力されます。
$ sudo bpftrace stack.bt
Attaching 2 probes...
Start tracing.
main.Fib+0
net/http.HandlerFunc.ServeHTTP+41
net/http.(*ServeMux).ServeHTTP+429
net/http.serverHandler.ServeHTTP+142
net/http.(*conn).serve+1512
net/http.(*Server).Serve.gowrap3+40
runtime.goexit.abi0+1
^C出力されたスタックトレースをnet/httpのソースコードと照らし合わせながら辿っていくと、(*Server).Serveにおいて(*conn).serveごとにゴルーチンを実行していることがわかります。
https://github.com/golang/go/blob/go1.22.1/src/net/http/server.go#L3285
(*conn).serveのserverHandler.ServeHTTPを呼び出している周辺のコードを読むと、(*response).finishRequestを呼び出している箇所があります。
https://github.com/golang/go/blob/go1.22.1/src/net/http/server.go#L2039-L2045
(*response).finishRequestではレスポンスヘッダやレスポンスボディの最終的な書き込みが行われているようです。
https://github.com/golang/go/blob/go1.22.1/src/net/http/server.go#L1662-L1669
また、http.response構造体を見るとそのメンバにリクエストの情報が含まれていることがわかります。
https://github.com/golang/go/blob/go1.22.1/src/net/http/server.go#L424
これを踏まえて、今回の実装ではserverHandler.ServeHTTPの開始から*response.finishRequestの終了までの間を1リクエストのトレース範囲とします。
トレースの実行
トレース範囲を決定したので、HTTPリクエスト・レスポンスの情報をトレースするbpftraceスクリプトを作成します。最終的に以下のようなコードとなりました。
// https://github.com/golang/go/blob/go1.22.1/src/runtime/runtime2.go#L422-L530
struct g {
uint8_t padding[152];
int64_t goid;
}
// https://github.com/golang/go/blob/go1.22.1/src/net/http/server.go#L421-L493
struct response {
uint8_t *conn;
struct request *request;
uint8_t padding1[40];
struct w *w;
uint8_t padding2[48];
int64_t contentLength;
int status;
};
// https://github.com/golang/go/blob/go1.22.1/src/net/http/request.go#L105-L333
struct request {
uint8_t *Method;
int MethodLen;
uint8_t *URL;
uint8_t *Proto;
int ProtoLen;;
uint8_t padding[136];
uint8_t *RemoteAddr;
int RemoteAddrLen;
uint8_t *RequestURI;
int RequestURILen;
}
// https://github.com/golang/go/blob/go1.22.1/src/bufio/bufio.go#L570-L581
struct w {
uint8_t padding[16];
uint8_t *buf;
}
BEGIN {
printf("Start tracing.\n");
}
uprobe:./app:runtime.execute {
$g = (struct g *)(reg("ax"));
@g[pid, tid] = $g->goid;
}
uprobe:./app:net/http.serverHandler.ServeHTTP /@g[pid, tid]/ {
$goid = @g[pid, tid];
@start[pid, $goid] = nsecs;
}
// (*response).finishRequest のアセンブリ
//
// 0000000000611240 <net/http.(*response).finishRequest>:
// 611240: 49 3b 66 10 cmp 0x10(%r14),%rsp
// 611244: 0f 86 b0 00 00 00 jbe 6112fa <net/http.(*response).finishRequest+0xba>
// 61124a: 55 push %rbp
// 61124b: 48 89 e5 mov %rsp,%rbp
// 61124e: 48 83 ec 10 sub $0x10,%rsp
// 611252: 48 89 44 24 20 mov %rax,0x20(%rsp) // <= rsp + 0x20にRAXの値(*http.response)が格納される
// ...
// 6112f4: 48 83 c4 10 add $0x10,%rsp // <= rsp + 0x10
// 6112f8: 5d pop %rbp // <= rsp - 0x08
// 6112f9: c3 ret // <= uprobeのアタッチ位置. 関数の先頭からのオフセットは0xb9(=185)
// ...
uprobe:./app:"net/http.(*response).finishRequest"+185 /@g[pid, tid]/ { // (*response).finishRequestのret命令
$goid = @g[pid, tid];
$start = @start[pid, $goid];
$latency = (nsecs - $start) / 1000;
// (*response).finishRequest の戻り値はないのでrspレジスタを元に取得します. オフセットはアセンブリから確認できます.
$resp = (struct response *)(*(reg("sp") + 0x08 - 0x10 + 0x20)); // *http.response
$req = $resp->request;
// $reponseBody = str($resp->w->buf, $resp->contentLength); // レスポンスボディをトレースする場合はこちらを使用します
printf(
"date_access:%s\tpid:%d\tgoid:%d\tremote_addr:%s\tmethod:%s\trequest_uri:%s\tproto:%s\tstatus:%d\tcontent_length:%d\tlatency:%d\n",
strftime("%Y-%m-%dT%H:%M:%S.%f%z", $start),
pid,
$goid,
str($req->RemoteAddr, $req->RemoteAddrLen),
str($req->Method, $req->MethodLen),
str($req->RequestURI, $req->RequestURILen),
str($req->Proto, $req->ProtoLen),
$resp->status,
$resp->contentLength,
$latency
);
delete(@start[pid, $goid]);
}
END {
clear(@g);
}トレースを実行し、再度/fib/{n}エンドポイントにリクエストを送信します。リクエスト・レスポンスの情報をトレースできていることが確認できます。
$ sudo bpftrace trace.bt
Attaching 5 probes...
Start tracing.
date_access:2024-03-17T23:20:56.289923+0900 pid:68288 goid:33 remote_addr:127.0.0.1:37076 method:GET request_uri:/ proto:HTTP/1.1 status:302 content_length:30 latency:17945
date_access:2024-03-17T23:20:56.312019+0900 pid:68288 goid:33 remote_addr:127.0.0.1:37076 method:GET request_uri:/fib/10 proto:HTTP/1.1status:200 content_length:9 latency:1949
date_access:2024-03-17T23:21:12.446807+0900 pid:68288 goid:39 remote_addr:127.0.0.1:41234 method:GET request_uri:/fib/2 proto:HTTP/1.1status:200 content_length:7 latency:6362
date_access:2024-03-17T23:21:12.456963+0900 pid:68288 goid:37 remote_addr:127.0.0.1:41224 method:GET request_uri:/fib/1 proto:HTTP/1.1status:200 content_length:7 latency:8234
date_access:2024-03-17T23:21:12.495367+0900 pid:68288 goid:38 remote_addr:127.0.0.1:41254 method:GET request_uri:/fib/4 proto:HTTP/1.1status:200 content_length:7 latency:592
date_access:2024-03-17T23:21:12.501565+0900 pid:68288 goid:36 remote_addr:127.0.0.1:41242 method:GET request_uri:/fib/3 proto:HTTP/1.1status:200 content_length:7 latency:732
date_access:2024-03-17T23:21:12.526999+0900 pid:68288 goid:6 remote_addr:127.0.0.1:41264 method:GET request_uri:/fib/7 proto:HTTP/1.1status:200 content_length:8 latency:384
date_access:2024-03-17T23:21:12.543766+0900 pid:68288 goid:21 remote_addr:127.0.0.1:41274 method:GET request_uri:/fib/5 proto:HTTP/1.1status:200 content_length:7 latency:490
date_access:2024-03-17T23:21:12.550955+0900 pid:68288 goid:8 remote_addr:127.0.0.1:41290 method:GET request_uri:/fib/6 proto:HTTP/1.1status:200 content_length:7 latency:388
date_access:2024-03-17T23:21:12.567956+0900 pid:68288 goid:23 remote_addr:127.0.0.1:41292 method:GET request_uri:/fib/8 proto:HTTP/1.1status:200 content_length:8 latency:357
date_access:2024-03-17T23:21:12.574497+0900 pid:68288 goid:10 remote_addr:127.0.0.1:41308 method:GET request_uri:/fib/10 proto:HTTP/1.1status:200 content_length:9 latency:409
date_access:2024-03-17T23:21:12.585184+0900 pid:68288 goid:11 remote_addr:127.0.0.1:41312 method:GET request_uri:/fib/9 proto:HTTP/1.1status:200 content_length:8 latency:346まとめ
本記事ではbpftraceを用いたGoアプリケーションのトレース方法に焦点を当て、その基本的な原理と使用方法、課題の解決策を紹介しました。
eBPFやbpftraceなどのツールを活用することで、Goアプリケーションの挙動をリアルタイムに観察し、パフォーマンスボトルネックの特定や障害の原因究明が可能になります。Goランタイムやアプリケーションの深い理解が求められる場面もありますが、これらのツールの適切な使い方を習得すれば、アプリケーションの振る舞いをより深く把握できるようになります。
eBPFの応用範囲は広く、オブザーバビリティだけでなく、セキュリティ、ネットワークなど、幅広い領域で活躍が期待されています。
eBPFやbpftraceに関心がある方は、eBPFプロジェクトページやbpftraceのプロジェクトページから最新情報を入手することをお勧めします。また、これらの学習を深めたい方は以下の書籍がお勧めです。
本記事がeBPFやbpftraceを用いたオブザーバビリティの強化、そしてGoアプリケーションのパフォーマンスと信頼性向上に貢献できれば幸いです。