このブログは、昨日の分です。だめですかね...
カーネルトレーシングシリーズです。今日は、Nginxを、追ってみます。
まず、 uprobe が見えるnginxバイナリを用意する
大抵の場合、パッケージのnginxバイナリはシンボルがstripされていて、uprobeが見えない。 nginx-build などで自分でビルドする。
トレーシングの都合上、 --with-debug でビルドするといいらしい（ ngx_request_t * などがトレーサから見えるようになる）。
$ nginx-build -d src/nginx-build -v 1.15.12 \
--with-debug
uprobeは以下の通り確認できる。
$ sudo bpftrace -l 'uprobe:/usr/local/nginx/sbin/nginx' | head uprobe:/usr/local/nginx/sbin/nginx:deregister_tm_clones uprobe:/usr/local/nginx/sbin/nginx:register_tm_clones uprobe:/usr/local/nginx/sbin/nginx:__do_global_dtors_aux uprobe:/usr/local/nginx/sbin/nginx:frame_dummy uprobe:/usr/local/nginx/sbin/nginx:ngx_load_module uprobe:/usr/local/nginx/sbin/nginx:ngx_unload_module uprobe:/usr/local/nginx/sbin/nginx:ngx_set_env uprobe:/usr/local/nginx/sbin/nginx:ngx_set_cpu_affinity uprobe:/usr/local/nginx/sbin/nginx:ngx_set_priority uprobe:/usr/local/nginx/sbin/nginx:ngx_set_worker_processes
リクエストごとに呼ばれるprobeを確認する
Nginx がリクエストのたびにこれらの関数をどう呼ぶかは、 Development guide に詳しい。
実際に吐き出して確認してみよう。
$ sudo bpftrace -e '
uprobe:/usr/local/nginx/sbin/nginx:ngx_http_*_connection { printf("Passed: %s\n", probe); }
uprobe:/usr/local/nginx/sbin/nginx:ngx_http*request* { printf("Passed: %s\n", probe); }
'
Attaching 84 probes...
別の窓で curl localhost とでもしてみると、様々な関数を通過していることが見える。
Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_init_connection Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_wait_request_handler Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_create_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_process_request_line Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_read_request_header Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_parse_request_line Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_process_request_uri Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_process_request_headers Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_read_request_header Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_process_request_header Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_process_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_discard_request_body Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_connection Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_close_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_connection Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_free_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_log_request Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_variable_request_line Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_run_posted_requests Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_run_posted_requests Passed: uprobe:/usr/local/nginx/sbin/nginx:ngx_http_close_connection
あるprobeから別のprobeまでかかった時間を計測する
uprobe:/usr/local/nginx/sbin/nginx:ngx_http_read_request_header /!@start[tid]/ { // printf("[%ld] Passed: %s (%p)\n", tid, probe, arg1); @start[tid] = nsecs } uretprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_connection /@start[tid]/ { @reqtime = hist(nsecs - @start[tid]); delete(@start[tid]); } END { clear(@start); }
こういうファイルを用意する。 ngx_http_read_request_header および ngx_http_finalize_connection は、 ngx_request_t * を引数にとる関数で、上記のようにそれぞれリクエストの最初の方と最後の方で呼ばれる。
リクエストを識別するマーカーとしてリクエストをしているスレッドのID、 tid を利用できる。今回は関数間での経過時間を測るのに使っている。
このファイルを reqtime.bt とでもして bpftrace で実行:
$ bpftrace reqtime.bt
別窓で ab をかける。
$ ab -c 300 -n 10000 http://localhost/
ab の後で C-c するとリクエスト時間の分布がわかる。ただし単位は、ナノ秒なので、 1M が1ミリ秒相当...。あと、件数がちゃんと 10,000 になっているのも確認する。
^C @reqtime: [32K, 64K) 9425 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [64K, 128K) 394 |@@ | [128K, 256K) 111 | | [256K, 512K) 13 | | [512K, 1M) 1 | | [1M, 2M) 1 | | [2M, 4M) 15 | | [4M, 8M) 27 | | [8M, 16M) 12 | | [16M, 32M) 1 | |
これとab側の結果を見比べるとまあ妥当な感じがする。無論、外からのリクエストはより若干オーバーヘッドがあるのでこっちの方が全体に数字が大きい。
Percentage of the requests served within a certain time (ms) 50% 18 66% 20 75% 22 80% 23 90% 28 95% 33 98% 39 99% 1430 100% 1855 (longest request)
システムコールを観測する
次に「リクエストの間に呼ばれるシステムコール」を観測したい。
uprobe:/usr/local/nginx/sbin/nginx:ngx_http_read_request_header /!@start[tid]/ { @start[tid] = 1; } tracepoint:raw_syscalls:sys_enter /@start[tid]/ { printf("[%ld] Called: %ld\n", tid, args->id); } uretprobe:/usr/local/nginx/sbin/nginx:ngx_http_finalize_connection /@start[tid]/ { delete(@start[tid]); } END { clear(@start); }
こういうスクリプトを書くと
- あるprobeが呼ばれたら
@start[tid]をセット @start[tid]が存在する状態でスレッドで呼ばれたシステムコールを記録- あるprobeにたどり着いたら
@start[tid]を削除
ということができる。実際、こういう感じのログになる。
$ sudo bpftrace syscalls.bt Attaching 4 probes... # 別窓で curl localhost [4617] Called: 4 [4617] Called: 257 [4617] Called: 5 [4617] Called: 20 [4617] Called: 40 # 以下同様 [4617] Called: 4 [4617] Called: 257 [4617] Called: 5 [4617] Called: 20 [4617] Called: 40 [4617] Called: 4 [4617] Called: 257 [4617] Called: 5 [4617] Called: 20 [4617] Called: 40
システムコール番号→名前、は、 ausyscall などのコマンドで確認。
$ for nr in 4 257 5 20 40; do echo -n $nr:; ausyscall $nr ; done 4:stat 257:openat 5:fstat 20:writev 40:sendfile
普通の処理で妙なシステムコール呼び出しが問題になることはないと思うが、 openresty や ngx_mruby などを使いミドル側で複雑なことをしている場合は便利かもしれない。
リクエスト単位のシステムコールを追いかけるのは strace などの既存技術では極めて難しいが、eBPFならこういう形でできるという話でもある。
気が向いたら他のミドルでも素振りをしてみたいところ。リクエストがあれば...。
