eBPFでコンテキストスイッチにかかる時間を測る その2
この記事は、ニューノーマル ぴょこりんクラスタ Advent Calendar 2020 のために書いたものです。 このAdvent Calendarが何なのかについては、主催者による紹介記事を見てください。
サマリ
前回の記事で書いたctxswstatについて、実装で気をつけたところについて話します。
はじめに
前回の記事では、Linux Kernelのschedule関数の開始と終了でタイムスタンプ取ればいい、
という話をしました。が、これを素直にやると結果が不穏になるので、
実はいくつか例外を設けています。今回はその例外の話をします。
計測したい区間の確認
自分は結局何を測定したかったか、についてまずは確認します。 もともとは、アクティブなプロセスから別のプロセスへ 切り替わるときの時間が知りたいということでした。 例えば、プロセスAとBがあったとして、 A→B→A→B...みたいな切り替わり方をした際に、 A→B、B→Aの時間が知りたいということです。なんか漠としてますね。 ともかく、暇じゃないときのコンテキストスイッチ時間が知りたいということです。
コンテキストスイッチの挙動をみてみる
さて、ではコンテキストスイッチの挙動を見てみましょう。
以下は、schedule関数の先頭(トレース上でのhello)、末尾(トレース上でのgoodbye)、そしてsched_switch
トレースポイント*1(トレース上でのswitch!!)で
printfしたログの、特にCPU#0についての抜粋です。
これは期待通りのケースと言えそうです。
kworker/u4:0-21407 [000] d..3 1100.097143: bpf_trace_printk: hello 1100051812115 25779' kworker/u4:0-21407 [000] d..4 1100.097144: bpf_trace_printk: switch!!' kworker/u4:1-84 [000] d..4 1100.097145: bpf_trace_printk: goodbye 2021 25780'
こういうのもまあ期待通りと言えるかもしれません。1回のschedule関数コールで
2回以上スイッチすることもあるんですね。
kworker/u4:0-21407 [000] d..3 1100.097181: bpf_trace_printk: hello 1100051849979 25781 kworker/u4:0-21407 [000] d..4 1100.097185: bpf_trace_printk: switch!!' tmux: server-327 [000] d..4 1100.097235: bpf_trace_printk: switch!!' kworker/u4:0-21407 [000] d..4 1100.097237: bpf_trace_printk: goodbye 56102 25783'
アクティブなプロセスが少ないと、そもそもコンテキストスイッチしないこともあるようです。
python-21734 [000] d..3 1111.979250: bpf_trace_printk: hello 1111932997396 2' python-21734 [000] d..4 1111.979261: bpf_trace_printk: goodbye 11062 2' python-21734 [000] d..3 1111.979281: bpf_trace_printk: hello 1111933028596 2' python-21734 [000] d..4 1111.979290: bpf_trace_printk: goodbye 8405 2' python-21734 [000] d..3 1111.979315: bpf_trace_printk: hello 1111933062140 2' python-21734 [000] d..4 1111.979323: bpf_trace_printk: goodbye 8636 2'
ここまではわかる気がしますが、ここからだんだんよくわからなくなってきます。 helloのトレースが出ずにswitchがたくさん出ていますね？？？？なにこれ？？？？
kworker/u4:0-21407 [000] d..4 1100.100453: bpf_trace_printk: goodbye 459911 25875'
kworker/u4:0-21407 [000] d..4 1100.100477: bpf_trace_printk: switch!!'
tmux: server-327 [000] d..4 1100.100514: bpf_trace_printk: switch!!'
kworker/u4:0-21407 [000] d..4 1100.100523: bpf_trace_printk: switch!!'
tmux: server-327 [000] d..4 1100.100533: bpf_trace_printk: switch!!'
<idle>-0 [000] d..4 1100.109520: bpf_trace_printk: switch!!'
rcu_preempt-11 [000] d..4 1100.109532: bpf_trace_printk: switch!!'
<idle>-0 [000] d..4 1100.110930: bpf_trace_printk: switch!!'
tmux: server-327 [000] d..4 1100.110960: bpf_trace_printk: switch!!'
<idle>-0 [000] d..4 1100.112379: bpf_trace_printk: switch!!'
これはhello～switch～goodbyeの流れを守ってはいますが、異様にたくさんコンテキストスイッチしているように見えます。idleプロセスでコンテキストスイッチ処理は終わらないのでしょうか？？？？
python-21734 [000] d..3 1113.240070: bpf_trace_printk: hello 1113193717909 11112' python-21734 [000] d..4 1113.240090: bpf_trace_printk: switch!!' <idle>-0 [000] d..4 1113.240114: bpf_trace_printk: switch!!' (ひたすらpython-21734と<idle>-0のペアを約2万行繰り返す) python-21734 [000] d..4 1113.443566: bpf_trace_printk: goodbye 203480015 24356'
これは別のときに取ったデータです。数値->数値のところはswitchと読み替えてください。 helloだけが続くケースや、hello～switch～helloもあるようです。
kworker/0:3-2488 [000] ...2 16220.930938: 0: hello 16220518525039, 2488
kworker/0:3-2488 [000] d..3 16220.930941: 0: 2488 -> 3486'
python-3486 [000] ...2 16220.930990: 0: hello 16220518576532, 3486
python-3486 [000] ...2 16220.931008: 0: hello 16220518595307, 3486
python-3486 [000] ...2 16220.931026: 0: hello 16220518612441, 3486
python-3486 [000] ...2 16220.931043: 0: hello 16220518629470, 3486
python-3486 [000] ...2 16220.931060: 0: hello 16220518646483, 3486
python-3486 [000] ...2 16220.931076: 0: hello 16220518663401, 3486
python-3486 [000] ...2 16220.931093: 0: hello 16220518680288, 3486
python-3486 [000] ...2 16219.360783: 0: hello 16218948354697, 3486'
python-3486 [000] d..3 16219.360815: 0: 3486 -> 11'
rcu_preempt-11 [000] ...2 16219.360819: 0: hello 16218948391244, 11'
rcu_preempt-11 [000] d..3 16219.360822: 0: 11 -> 3486'
python-3486 [000] d..3 16219.360823: 0: goodbye 16218948395547, 3486'
事例からわかる例外の整理
これらの事例と対策を整理すると、以下のようになります。
schedule関数が呼ばれて、1回以上コンテキストスイッチすることもある → コンテキストスイッチ回数を取得し、1回あたりの平均を計算できるようにする。 コンテキストスイッチ回数が0回の場合は時間計測しないようにする。- pid 0のidleプロセス*2で コンテキストスイッチ処理は終わらないのかもしれない。 →idleプロセスへのコンテキストスイッチ = 暇な状態、ということなので、pid 0への/からのコンテキストスイッチが混ざるケースは時間計測しないようにする。
schedule関数が何度も呼ばれたように見えるが、コンテキストスイッチもschedule関数終了もしていないように 見えることもある → 最後のschedule関数開始から時間計測を開始するscheudule関数が呼ばれて、少なくとも1回コンテキストスイッチした後、schedule関数終了前に 再度schedule関数が呼ばれることもある → コンテキストスイッチ自体はできているはずなので、schedule関数開始～次のschedule関数開始までを 測定区間とする。schedule関数が呼ばれずにコンテキストスイッチしたように見えることもある。 →schedule関数が呼ばれていない場合のコンテキストスイッチは無視する。
状態遷移図っぽいもの*3はこんな感じです。
終わりに
多少例外はありますが、コンテキストスイッチはこんな感じで測っています。
