前回はBCC(Berkely Compiler Collection)を使い、カーネルのトレースを実行してみました。
カーネルの命令が実行される前にはkprobeを使い、実行の後にはkretprobeを使います。
同様に、アプリケーション（OS上で動作するソフトウェア）が使用するメモリ領域のユーザースペースのプログラムにもトレースすることができます。
UPROBES
次のような、Goプログラムがあるとします。
$ cat main.go
package main
import "fmt"
func main() {
fmt.Println("Hello!")
}
このプログラムをコンパイルして、バイナリファイルに含まれる命令ポイントに関する情報を取得してみます。
$ go build -o hello main.go
$ nm hello|grep main
000000000054ee20 D main..inittask
0000000000491990 T main.main
00000000004da3b0 R main.main.stkobj
0000000000431610 T runtime.main
0000000000458da0 T runtime.main.func1
...
例えば、main関数をトレースするBPFプログラムを作成し、命令が実行される前にトレースするには、attach_uprobe()を利用します。
$ cat example.py
#!/usr/bin/python3
from bcc import BPF
bpf_source = """
int trace_go_main(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
bpf_trace_printk("New hello process running with PID: %d\\n", pid);
return 0;
}
"""
bpf = BPF(text = bpf_source)
bpf.attach_uprobe(name = "./hello", sym = "main.main", fn_name = "trace_go_main")
bpf.trace_print()
example.pyを実行しているときに、helloプログラムを実行すると、次のようにユーザースペースのトレースができるようになります。
$ ./example.py
b' <...>-91154 [001] .... 526446.516494: 0: New hello process running with PID: 91154'
b' <...>-91158 [001] .... 526449.188449: 0: New hello process running with PID: 91158'
URRETPROBES
uretprobesも、ユーザースペースのプログラムをトレースできます。
uretprobesとuprobesを組み合わせることにより、アプリケーションに変更を加えることなく正確な実行時間を測定することもできます。
先程のプログラムのmain関数を実行するのにどれくらいの時間を要したかを調べるには、次のようにして求めることができます。
$ cat example.py
#!/usr/bin/python3
from bcc import BPF
bpf_source = """
BPF_HASH(cache, u64, u64);
int trace_start_time(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
u64 start_time_ns = bpf_ktime_get_ns();
cache.update(&pid, &start_time_ns);
return 0;
}
"""
bpf_source += """
int print_duration(struct pt_regs *ctx) {
u64 pid = bpf_get_current_pid_tgid();
u64 *start_time_ns = cache.lookup(&pid);
if (start_time_ns == 0) {
return 0;
}
u64 duration_ns = bpf_ktime_get_ns() - *start_time_ns;
bpf_trace_printk("Function call duration: %d nano seconds\\n", duration_ns);
return 0;
}
"""
bpf = BPF(text = bpf_source)
bpf.attach_uprobe(name = "./hello", sym = "main.main", fn_name = "trace_start_time")
bpf.attach_uretprobe(name = "./hello", sym = "main.main", fn_name = "print_duration")
bpf.trace_print()
ここでは、BPF_HASHを使い、アプリケーションのPIDをキーにして、開始時間を保存しています。
カーネルから現在時刻を取得し、その差分をナノセカンドで表示します。
ナノセカンドとは、10億分の1秒と、ほんのわずかな一瞬です。
実行するとこのような結果を取得することができます。
# ./example.py
b' hello-4220 [000] .... 7443.220040: 0: Function call duration: 79596 nano seconds'
b' hello-4224 [000] .... 7445.553920: 0: Function call duration: 144259 nano seconds'
b' hello-4228 [000] .... 7447.953574: 0: Function call duration: 142904 nano seconds'
b' hello-4232 [000] .... 7449.448930: 0: Function call duration: 108950 nano seconds'
b' hello-4244 [000] .... 7452.371757: 0: Function call duration: 62631 nano seconds'
まとめ
timeなどのコマンドでもプログラムの実行時間(秒)を求めることができますが、より詳細なナノ秒を求めるには有効な方法かと思います。
また、アプリケーションに一切手を加えなくてもいいので、応用範囲も広がるかと思います。
コメント