ローファイ日記

出てくるコード片、ぼくが書いたものは断りがない場合 MIT License としています http://udzura.mit-license.org/

Haconiwaの起動〜execve、起動〜listenまでの時間をトレースできるようにした

昨日は普通にブログを忘れていた...。増税に負けてしまった...。

気を取り直して今日。

github.com

hacoboot_sampler というツールをリポジトリに同梱した（名前は...）。

# 第一引数は、コンテナの init のコマンドを推奨
$ sudo bpftrace misc/hacoboot_sampler.bt /u/app/helloworld/bin/rails

こう起動して、別窓でコンテナをあげたり降ろしたりしていると、

  • 起動（正確には、Haconiwa内部の最初のprobe）〜コンテナ自体がexecveするタイミングまで
  • 起動〜コンテナがポートリスンするまで

のそれぞれの時間を計測し、平均、最大、最小をナノ秒単位で出してくれる。

Attaching 5 probes...
^C

@execve__count: 3

@execve_avg: 70950886

@execve_max: 78633157

@execve_min: 59346736

@listen__count: 3

@listen_avg: 2240287035

@listen_max: 2359375184

@listen_min: 2100345924

このコンテナは execveまで平均 78ms、その後リスンしてアクセスできるようになるまで 2240ms かかっているとわかる。コンテナプロセスの起動自体の必要時間が 2100ms 程度ということですね。

スクリプトを参考に、ヒストグラムを出したり他の集計も試せるし、各値をTSVに吐き出してmatplotlibに食わせたり、など、夢が広がる。

今の制限として、initプロセス（スレッド）がそのままlisten(2)を発行するパターンでないとlistenの検知ができない。こういうときに cgroup が取れるとコンテナ内でのシステムコール呼び出しが紐づくんだけど、今回実際にやりたい環境は諸事情によりUbuntu 16.04なのでカーネルが新しくても4.15で、 BPF_FUNC_get_current_cgroup_id がないので使えないみたい。

みんな、カーネルどんどん上げていきましょう。Bionicで5.0が使えるんですよ、やばくないですか。

続きを読む

POSIX Timer で純粋に時間を測る

man7.org

sevp.sigev_notify を SIGEV_NONE にし、なおかつ非常に先の時間を expiration に指定すれば、その時間までの残り時間を timer_gettime(2) で取得できる。

あとは引き算をすればOK。「非常に先の時間」以上の時間を計測できないことになるが、 10億秒（31年）などを指定すれば用は足りそう。

続きを読む

Haconiwaのprobeを少し整理した

github.com

今までタイムスタンプを clock_gettime でとっていたけど、そのタイムスタンプはカーネル側でつけてくれるような気がしたので外した。それよりも、同じコンテナ管理プロセスでのイベントかどうかを見分けたいので、hpidという数字を発行することにした（といってもhaconiwa svのPIDなのだが、fork-execの間でも親と同じ値を渡すようにした。本当は、C側でuuid並みの大きな数字を発行するのが良さそう）。

いっしょにprobeの名前を変更（bpftraceでは - を含むprobe名を利用できない模様）したり、bpftraceで動くサンプルをつけた。

Haconiwaが特定の処理を通過するとき、現在のマスターではこんな感じのbpftraceスクリプトを書くとイベントをフィルターできる。イベントの数値は、似たようなものは ~10、 11~30, 31~, 100~127 のように近づけて定義しているので。

BEGIN { printf("Starting trace...\n"); }
usdt:./mruby/bin/haconiwa:haconiwa:bootstrap_phase_pass /arg0 > 10/ {
        printf("[%d] Pass: hpid: %d, phase: %d\n", nsecs, arg1, arg0);
}

$ sudo bpftrace misc/sample.bt                                                         
Attaching 2 probes...
Starting trace...

[1262986711] Pass: hpid: 26454, phase: 11
[1286217066] Pass: hpid: 26454, phase: 12
[1288785734] Pass: hpid: 26454, phase: 13
[1288810441] Pass: hpid: 26454, phase: 14
[1288848938] Pass: hpid: 26454, phase: 15
[1289587716] Pass: hpid: 26454, phase: 16
[1289756137] Pass: hpid: 26454, phase: 17
[1290851274] Pass: hpid: 26454, phase: 18
[1295379411] Pass: hpid: 26454, phase: 19
[1295399850] Pass: hpid: 26454, phase: 20
[1296817400] Pass: hpid: 26454, phase: 21
...

多分、これの対応を含んだヘッダーとかを用意したら、bpftraceの --include で読み込んで人間にわかりやすく表示できると思う（そういう認識）。

これでもそれぞれの経過時間は雰囲気でわかるが（あるいは頑張って計算すればわかる）、カーネルタイマーを使って直接probeできないかなあ？ というのを考えているところ。

今日はこんな感じメモ並みの内容です。

eBPF でイベントが起こったプロセスの cgroup IDを取るには

bpftrace には cgroup という変数があって、イベントが起こったプロセスの cgroup ID（後述しますが、？な数字です）を取得できます。

$ bpftrace -e 'uretprobe:/bin/bash:readline { printf("input(%d@%d) = %s\n", pid, cgroup, str(retval)); }'
Attaching 1 probe...

input(16277@2055) =
input(16277@2055) = echo $$ > /sys/fs/cgroup/unified/sample100/cgroup.procs # <= ここで変更
input(16277@2139) = ls -l
続きを読む