eBPFでコンテキストスイッチにかかる時間を測る その1

この記事は、ニューノーマル ぴょこりんクラスタ Advent Calendar 2020 のために書いたものです。 このAdvent Calendarが何なのかについては、主催者による紹介記事を見てください。

はじめに

コンテキストスイッチの処理時間がどうこう言われるケースって、現実的には そうないと思います。しかし、例えばプロセスやスレッドをCPUコア数に対して たくさん起こすケースで、特に性能を追い求めたい場合、 気になることもあるでしょう*1。 世の中のツールをざっと見渡してみても、コンテキストスイッチの回数は 測定できても*2、 時間は測定できないようです。困りましたね。 困るくらいなら作ってみましょう。

本記事では、Linuxにおけるコンテキストスイッチの時間を測るプログラムについて考えてみます。

成果物

github.com

sudoを使うなりrootになった上で、 ./ctxswstatと実行するだけで使えます。 対象とするOSはLinuxです。 CPUごとに、合計コンテキストスイッチ回数、合計コンテキストスイッチ時間、 平均コンテキストスイッチ時間、1秒間に占めるコンテキストスイッチ時間の割合が 表示がされます。warningは消せなかった・・・

bisco@butterscotch /home/bisco/work/ctxswstat main(62e91f3)
> sudo ./ctxswstat
/virtual/main.c:74:1: warning: non-void function does not return a value [-Wreturn-type]
}
^
1 warning generated.
time of context switch [unit:nsec]
count      cpu1       cpu2
2     cnt: 0          4
2     tot: 0          26166
2     avg: 0.00       6541.50
2       %: 0.00       0.00
3     cnt: 0          2
3     tot: 0          111305
3     avg: 0.00       55652.50
3       %: 0.00       0.01
4     cnt: 0          1
4     tot: 0          246338
4     avg: 0.00       246338.00
4       %: 0.00       0.02
5     cnt: 8          1
5     tot: 75519      6131
5     avg: 9439.88    6131.00
5       %: 0.00       0.00

動作確認環境は以下のとおりです。

コンテキストスイッチとはなにか

コンテキストスイッチとは、実行中のプロセスの状態を保存し、 別の保存されているプロセスの状態を復元することです。 大枠はWikipediaを見てください。 状態とは、プロセスの実行中のレジスタの値のことなので、 状態の保存 = ある瞬間のレジスタの値をメモリに退避、 状態の復元 = メモリ上に退避されていた値をレジスタに書き込む、 と読んでいただければと思います。

Linuxにおけるコンテキストスイッチ処理は、スケジューラが実行します。 スケジューラが次にどのプロセスを動かすか決定し、 コンテキストスイッチを実行します*3。

何を測るか？

コンテキストスイッチはいきなり起こるのではなく、常にスケジューラとともに動きますので、 単にレジスタの読み書きの時間を測ることはあまり意味がなくて、 スケジューラの処理で消費する時間も測定が必要ということです。 ということで、スケジューラ処理にかかる時間+コンテキストスイッチにかかる時間を測ることにします。

Linuxでは、スケジューラ処理は、kernel/sched/core.cで定義されている scheduleという関数からスタートします。 コンテキストスイッチ処理は、context_switchという関数で行われますが、 これはschedule関数からコールされる__schedule関数からコールされます。 つまり、schedule関数にかかった時間を測ればよいということになります。

以降はほぼ余談ですが、schedule関数がどんなものかを一応見ておきます。

asmlinkage __visible void __sched schedule(void)
{
    struct task_struct *tsk = current;

    sched_submit_work(tsk);
    do {
        preempt_disable();
        __schedule(false);
        sched_preempt_enable_no_resched();
    } while (need_resched());
    sched_update_worker(tsk);
}
EXPORT_SYMBOL(schedule);

大まかには以下の4stepですね。

  1. schedule関数を再度呼ばれないようにする(=preempt_disable)
  2. __schedule関数を呼ぶ
  3. schedule関数を呼べるようにする
  4. __schedule関数を再度呼ぶ必要があれば、1.に戻る

どうやって測るか？

方針

schedule関数の処理時間を測れそうな手段として挙げられるのはこんなところでしょう。 今回は、最近ホットなeBPFを使います。

  1. Kernelにトレースを自前で入れて測る
  2. kprobeを使う
  3. systemtapを使う
  4. eBPFを使う

eBPFとは、ユーザが作成したプログラムをカーネル内で実行する機能です。 偉大な先人が書いた記事がいっぱいあるので、本記事では説明を省略しますが、 個人的には これがわかりやすくていいなと思います。

以降、実装の要点について説明します。

実装の要点1：コンテキストスイッチ時間の計算

eBPFには、関数の先頭と末尾をフックして関数コールする機能がありますので、 それを使います。関数先頭と末尾でタイムスタンプを取得して、 末尾でタイムスタンプの差分を計算します。 ソースコードの中身でいうとこのあたりです。

// kprobe__<関数名>とすると、<関数名>で表される関数の先頭でコールされる
// 関数を定義できる
void kprobe__schedule(struct pt_regs* ctx) {
    __do_count_begin(bpf_get_smp_processor_id());
}

// kretprobe__<関数名>とすると、<関数名>で表される関数の末尾でコールされる
// 関数を定義できる
void kretprobe__schedule(struct pt_regs* ctx) {
    __do_count_end(bpf_get_smp_processor_id());
}

bpf_get_smp_processor_id関数は、このプログラムがコールされたCPUコア番号を取得する関数です。 スケジューラは(ある意味当然ですが)CPUコア単位で並列に動作するので、 差分計算時に、どのコアにおける差分なのか区別をつけるために使います。

実装の要点2：表示のための処理

これで計算ができそうですが、コンテキストスイッチはそれなりにたくさん発生しますので、 1個ずつ表示すると、表示処理の負荷と、見る方の負荷が大きくなってしまうことが想像できます。 ですので、一般的なツールにならって、一定周期で周期ごとの平均値を出すようにします。

ここでいう平均値は、回数あたりの平均、つまり (ある周期内の累積時間) / (ある周期内のコンテキストスイッチ回数)で算出するようにします。 関係するのはこのあたりです。前回取得したときの累積値を覚えておいて、 単に差分を取るだけです。

    def __calc_diff_and_avg(self):
        for i in range(self.cpu_count):
            self.diff_acc_time[i]  = self.cur_acc_time[i] - self.prev_acc_time[i]
            self.diff_ctxsw_cnt[i] = self.cur_ctxsw_cnt[i] - self.prev_ctxsw_cnt[i]
            if self.diff_ctxsw_cnt[i] != 0:
                self.avg_ctxsw_time[i] = self.diff_acc_time[i] / self.diff_ctxsw_cnt[i]
                self.ctxsw_time_ratio[i] = self.avg_ctxsw_time[i] / self.ratio_const
            else:
                self.avg_ctxsw_time[i] = 0
                self.ctxsw_time_ratio[i] = 0

動作確認

動作確認環境で無負荷状態で試しに動かしてみたのが前述の出力例ですが、 数us～数百usほどの幅があるようです。何でそんなに差があるのかはわかりませんね・・・

レジスタの入れ替えは一定時間(せいぜい数us程度？)で終わるでしょうから、 幅の原因はコンテキストスイッチというよりは、スケジューラそのものの動作の影響か、 VMで動作することの影響ももしかしたらあるかもしれません。

終わりに

本記事では、LinuxにおいてeBPFを使ってコンテキストスイッチの時間を測る プログラムについて考えてみました。 次回、今回説明しなかった実装の細かいところ、 次々回、実際にいくつかプロセスがアクティブにCPUを取り合っている状況ではどうなっているのかを 記事にする予定です。

*1:そんな作りにするなという説もある

*2:例えばpidstatとか、/proc/[pid]/schedstatとか

*3:Linuxに限らず一般的なOSではそうだと思う