消費税増税に対抗し、10月はなるべく毎日営業日はブログを書こうと思います。
これのシリーズです。はてブが伸びなくても書いていく。消費税増税に対抗するのが目的ではてブは目的ではないから。
今日はトレーシングネタで、HaconiwaにUSDTを仕込んだ話をします。
USDTとは usdt mrtc0 で検索すると大体わかるのですが、ユーザランドの振る舞いをカーネルでトレースする uprobe を利用して、ユーザランドのプログラムに静的なフックポイントを入れてオーバヘッドをなるべく少なくトレースするような感じの機能です。
最近だと h2o にUSDTを仕込んでいるのを見たりしました。
で、Haconiwaでも入れてみました。
入れ方としては簡単で、C側で DTRACE_PROBE* というマクロを組み込んでprobeを埋め込む。それをmrubyのメソッドにして使う、という感じです。
static mrb_value mrb_haconiwa_probe_boottime(mrb_state *mrb, mrb_value self) { mrb_int flag; struct timespec tp; mrb_get_args(mrb, "i", &flag); (void)clock_gettime(CLOCK_BOOTTIME, &tp); // This won't be error DTRACE_PROBE3(haconiwa, probe-boottime, (long)flag, tp.tv_sec, tp.tv_nsec); return mrb_nil_value(); } //... void mrb_haconiwa_gem_init(mrb_state *mrb) { struct RClass *haconiwa; haconiwa = mrb_define_module(mrb, "Haconiwa"); mrb_define_class_method(mrb, haconiwa, "probe_boottime", mrb_haconiwa_probe_boottime, MRB_ARGS_REQ(1)); //... }
Haconiwa.probe_boottime(PHASE_XXX) を各所に仕込んで、そこを通過した時のタイムスタンプをprobeにする。
raise_container do |base| #.... pid = Process.fork do Haconiwa.probe_containergen(PHASE_CONTAINER_START) #... apply_namespace(base.namespace) Haconiwa.probe_containergen(PHASE_CONTAINER_NAMESPACE_GENERATED) #...
このprobeはトレーシングが無効の時はnop扱いで、ですが仕込まれた場所がELFヘッダのnoteに含まれています。
$ readelf -n ./mruby/bin/haconiwa
Displaying notes found in: .note.ABI-tag
Owner Data size Description
GNU 0x00000010 NT_GNU_ABI_TAG (ABI version tag)
OS: Linux, ABI: 3.2.0
Displaying notes found in: .note.gnu.build-id
Owner Data size Description
GNU 0x00000014 NT_GNU_BUILD_ID (unique build ID bitstring)
Build ID: 43c099d3cff2b8dd4ca500df10c094fb2cf38166
Displaying notes found in: .note.stapsdt
Owner Data size Description
stapsdt 0x00000048 NT_STAPSDT (SystemTap probe descriptors)
Provider: haconiwa
Name: probe-boottime
Location: 0x000000000007b973, Base: 0x00000000002164e0, Semaphore: 0x0000000000000000
Arguments: -8@%rax -8@%rdx -8@%rcx
stapsdt 0x0000004c NT_STAPSDT (SystemTap probe descriptors)
Provider: haconiwa
Name: probe-containergen
Location: 0x000000000007b9f4, Base: 0x00000000002164e0, Semaphore: 0x0000000000000000
Arguments: -8@%rax -8@%rdx -8@%rcx
stapsdt 0x0000003c NT_STAPSDT (SystemTap probe descriptors)
Provider: haconiwa
Name: probe-misc
Location: 0x000000000007ba6d, Base: 0x00000000002164e0, Semaphore: 0x0000000000000000
Arguments: -8@%rax -8@%rdx
stapsdt 0x0000003b NT_STAPSDT (SystemTap probe descriptors)
Provider: haconiwa
Name: probe-misc
Location: 0x000000000007ba93, Base: 0x00000000002164e0, Semaphore: 0x0000000000000000
Arguments: -8@%rbx 8@%rax
stapsdt 0x0000003b NT_STAPSDT (SystemTap probe descriptors)
Provider: haconiwa
Name: probe-misc
Location: 0x000000000007bae0, Base: 0x00000000002164e0, Semaphore: 0x0000000000000000
Arguments: -8@%rax 8@%rdx
この情報のおかげで、有効の時だけに動的にprobe化させることができるそう。
具体的にトレースして見てみます。バイナリ単位でトレースを有効にする。
# Originated from # https://github.com/brendangregg/bcc/blob/master/examples/tracing/nodejs_http_server.py # 一部省略 haconiwa_path_or_pid = sys.argv[1] bpf_text = """ #include <uapi/linux/ptrace.h> int do_trace(struct pt_regs *ctx) { uint64_t addr1, addr2, addr3; long flag, tv_sec, tv_nsec; bpf_usdt_readarg(1, ctx, &addr1); bpf_usdt_readarg(2, ctx, &addr2); bpf_usdt_readarg(3, ctx, &addr3); bpf_probe_read(&flag, sizeof(flag), (void *)&addr1); bpf_probe_read(&tv_sec, sizeof(tv_sec), (void *)&addr2); bpf_probe_read(&tv_nsec, sizeof(tv_nsec), (void *)&addr3); bpf_trace_printk("phase:%ld,sec:%ld,nsec:%ld\\n", flag, tv_sec, tv_nsec); return 0; }; """ b = None if os.path.exists(haconiwa_path_or_pid): print("tracing program %s" % haconiwa_path_or_pid) u = USDT(path=haconiwa_path_or_pid) u.enable_probe(probe="probe-boottime", fn_name="do_trace") b = BPF(text=bpf_text, usdt_contexts=[u]) print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "VALUE")) # format output while 1: try: (task, pid, cpu, flags, ts, msg) = b.trace_fields() except ValueError: print("value error") continue except KeyboardInterrupt: exit() printb(b"%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))
こうすると、いちいちコンテナ起動のたびにpidを探さなくても、全部トレースをやってくれる。
$ sudo python misc/trace_usdt.py ./mruby/bin/haconiwa tracing program ./mruby/bin/haconiwa
別ターミナルで。
$ sudo ./mruby/bin/haconiwa run sample/hooks.haco
そうすると:
TIME(s) COMM PID VALUE 102935.009095000 haconiwa 28804 phase:1,sec:102949,nsec:842200234 102935.156848000 <...> 28806 phase:2,sec:102949,nsec:989952375 102935.157180000 haconiwa 28810 phase:11,sec:102949,nsec:990286467 102935.173341000 haconiwa 28810 phase:12,sec:102950,nsec:6447448 102935.174323000 haconiwa 28810 phase:13,sec:102950,nsec:7431463 102935.174349000 haconiwa 28810 phase:14,sec:102950,nsec:7460188 102935.174451000 haconiwa 28810 phase:15,sec:102950,nsec:7560534 102935.174952000 haconiwa 28810 phase:16,sec:102950,nsec:8061304 102935.175210000 haconiwa 28810 phase:17,sec:102950,nsec:8318743 102935.194515000 haconiwa 28810 phase:18,sec:102950,nsec:27620084 102935.199899000 haconiwa 28810 phase:19,sec:102950,nsec:33002605 102935.200039000 haconiwa 28810 phase:20,sec:102950,nsec:33149341 102935.200512000 haconiwa 28806 phase:3,sec:102950,nsec:33620753 102935.200709000 haconiwa 28810 phase:21,sec:102950,nsec:33817740 102935.216007000 haconiwa 28806 phase:4,sec:102950,nsec:49112344 102940.280878000 haconiwa 28806 phase:124,sec:102955,nsec:113981855 ...
phaseが 11 <= x < 100 のものはコンテナがforkしたあと、execveする間の様々なコンテナ化の処理のフェーズごとのprobeです。マジックナンバーを辿ると、たとえばnamespaceの作成に150msぐらいかかってる、pivot_rootに190msぐらいかかってそう、みたいなのが読み取れる。
このprobeは無効の時はnopになっていてパフォーマンスへの影響が最低限（触った感じ、有効にしていてもオーバーヘッドがよくわからないぐらい...）なので、本番環境にいれてみる障壁も低いのかなーなどと思います。
そしてそもそもUSDTってこういう使い方でいいのかがわからんので色々ご指導ご鞭撻が欲しい...
そんな感じで。
