Linuxの各タスクにおけるスケジューリング統計情報 (procfs)

##`/proc/<pid>/sched` の中身
[procのmanマニュアル](https://linuxjm.osdn.jp/html/LDP_man-pages/man5/proc.5.html)に書いてなかったので今まで全然気づいていなかったんですが、便利なスケジューリング統計情報をユーザが簡単に見れることを最近知りました。`/proc/<pid>/sched` です。

Ubuntu 14.04 で `pid=1` の `init` タスクの統計情報を見てみると以下のようになります。

```
$ cat /etc/os-release 
NAME="Ubuntu"
VERSION="14.04.4 LTS, Trusty Tahr"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 14.04.4 LTS"
VERSION_ID="14.04"
HOME_URL="http://www.ubuntu.com/"
SUPPORT_URL="http://help.ubuntu.com/"
BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/"
$ cat /proc/1/sched
init (1, #threads: 1)
-------------------------------------------------------------------
se.exec_start                                :     176686992.984163
se.vruntime                                  :           691.937721
se.sum_exec_runtime                          :          2342.115314
se.statistics.wait_start                     :             0.000000
se.statistics.sleep_start                    :     176686992.984163
se.statistics.block_start                    :             0.000000
se.statistics.sleep_max                      :      14095966.363585
se.statistics.block_max                      :          4216.956618
se.statistics.exec_max                       :            20.227471
se.statistics.slice_max                      :            40.150588
se.statistics.wait_max                       :            10.753266
se.statistics.wait_sum                       :           373.022241
se.statistics.wait_count                     :                13537
se.statistics.iowait_sum                     :          1696.874333
se.statistics.iowait_count                   :                  637
se.nr_migrations                             :                 1082
se.statistics.nr_migrations_cold             :                    0
se.statistics.nr_failed_migrations_affine    :                    0
se.statistics.nr_failed_migrations_running   :                  976
se.statistics.nr_failed_migrations_hot       :                  325
se.statistics.nr_forced_migrations           :                    1
se.statistics.nr_wakeups                     :                 6493
se.statistics.nr_wakeups_sync                :                 4405
se.statistics.nr_wakeups_migrate             :                 1046
se.statistics.nr_wakeups_local               :                 1244
se.statistics.nr_wakeups_remote              :                 5249
se.statistics.nr_wakeups_affine              :                  261
se.statistics.nr_wakeups_affine_attempts     :                 1197
se.statistics.nr_wakeups_passive             :                    0
se.statistics.nr_wakeups_idle                :                    0
avg_atom                                     :             0.174264
avg_per_cpu                                  :             2.164616
nr_switches                                  :                13440
nr_voluntary_switches                        :                 6474
nr_involuntary_switches                      :                 6966
se.load.weight                               :                 1024
se.avg.runnable_avg_sum                      :                  466
se.avg.runnable_avg_period                   :                47841
se.avg.load_avg_contrib                      :                    0
se.avg.decay_count                           :            168501848
policy                                       :                    0
prio                                         :                  120
clock-delta                                  :                  201
```

何やら色んな情報が出てますね。これを見れば、簡単にタスクがCPU上で実行していた時間とか、何回コンテキストスイッチをしたか、タスクのスリープ時間・起床回数などがわかりそうです。
正確には `/proc/<pid>/sched` はスレッドグループリーダの情報なので、そのスレッドグループに属する各スレッドの情報を見るには `/proc/<tgid>/task/<tid>/sched` を見る必要があります (***tgid*** はスレッドグループID、***tid*** はスレッドIDの意味)。

名前から想像はできそうですが、まず、そもそもどうやってこの情報を表示しているか  `procfs` の処理の中身を軽く追いかけたいと思います。カーネルソースを読むときは、まず大雑把に推測するのが一番良いかなと。細かい所ばかり追うと、いつまで経っても調査が終わらない場合が多いので・・・。

カーネルの中身なんて見たくない人にとっては、[各統計情報の意味](#各統計情報の意味)だけ読んでいただければいいかもしれません。ちょっとカーネル内部を追いかけたい人は、各統計情報の文字列をカーネルソースから検索すれば、どういう処理でどうカウントしてるかがわかってLinuxのタスクスケジューラの概要が理解できると思いますので試してみてください。


#`/proc/<pid>/sched` を open(2) した時のカーネル処理
[`pid_entry` 構造体の配列 `tgid_base_stuff`](http://lxr.free-electrons.com/source/fs/proc/base.c?v=3.13#L2571) を見てみましょう。

```:linux-3.13/fs/proc/base.c
2571 static const struct pid_entry tgid_base_stuff[] = {
2572         DIR("task",       S_IRUGO|S_IXUGO, proc_task_inode_operations, proc_task_operations),
2573         DIR("fd",         S_IRUSR|S_IXUSR, proc_fd_inode_operations, proc_fd_operations),
2574 #ifdef CONFIG_CHECKPOINT_RESTORE
2575         DIR("map_files",  S_IRUSR|S_IXUSR, proc_map_files_inode_operations, proc_map_files_operations),
2576 #endif
2577         DIR("fdinfo",     S_IRUSR|S_IXUSR, proc_fdinfo_inode_operations, proc_fdinfo_operations),
2578         DIR("ns",         S_IRUSR|S_IXUGO, proc_ns_dir_inode_operations, proc_ns_dir_operations),
2579 #ifdef CONFIG_NET
2580         DIR("net",        S_IRUGO|S_IXUGO, proc_net_inode_operations, proc_net_operations),
2581 #endif
2582         REG("environ",    S_IRUSR, proc_environ_operations),
2583         INF("auxv",       S_IRUSR, proc_pid_auxv),
2584         ONE("status",     S_IRUGO, proc_pid_status),
2585         ONE("personality", S_IRUGO, proc_pid_personality),
2586         INF("limits",     S_IRUGO, proc_pid_limits),
2587 #ifdef CONFIG_SCHED_DEBUG
2588         REG("sched",      S_IRUGO|S_IWUSR, proc_pid_sched_operations),
2589 #endif
・・・（省略）・・・
```

内部で定義されている要素とメンバを眺めると、`/proc/<pid>` 配下のファイル名やディレクトリ名に一致する文字列が `DIR()` や `REG()` などの第一引数に並んでいることが分かります。ここで、恐らくディレクトリは `DIR()`、通常ファイル (regular file) は `REG()` で表現されてて、`pid_entry` 構造体を良い感じで定義すれば `procfs` 作れるんだろうなと想像できます。

第二引数にある `S_XXXXX` はアクセス権の設定ですね。この定義は [include/uapi/linux/stat.h](http://lxr.free-electrons.com/source/include/uapi/linux/stat.h?v=3.13) に書いてます。ファイルのアクセス権を変更する `chmod` コマンドで引数に渡す `mode` と同じ感じですし、[stat(2) の man マニュアルにも書いてくれてます](https://linuxjm.osdn.jp/html/LDP_man-pages/man2/stat.2.html)。
`ls -l /proc/<pid>` を実行した結果と`tgid_base_stuff` のメンバとを比較すると、設定通りにアクセス権が反映されていることがわかります。

```:linux-3.13/include/uapi/linux/stat.h
 27 #define S_IRWXU 00700
 28 #define S_IRUSR 00400
 29 #define S_IWUSR 00200
 30 #define S_IXUSR 00100
 31 
 32 #define S_IRWXG 00070
 33 #define S_IRGRP 00040
 34 #define S_IWGRP 00020
 35 #define S_IXGRP 00010
 36 
 37 #define S_IRWXO 00007
 38 #define S_IROTH 00004
 39 #define S_IWOTH 00002
 40 #define S_IXOTH 00001
```

今回追いたいのは `/proc/<pid>/sched` なので、この定義だけ着目しましょう。この情報を表示するには、カーネルコンフィグ `CONFIG_SCHED_DEBUG=y` に設定する必要があります。Ubuntu はデフォルト `y` みたいですね。

```
2587 #ifdef CONFIG_SCHED_DEBUG
2588         REG("sched",      S_IRUGO|S_IWUSR, proc_pid_sched_operations),
2589 #endif
```

第三引数には [`file_operations` 構造体](http://lxr.free-electrons.com/source/include/linux/fs.h?v=3.13#L1521)を指定してて、これはファイルの操作に対するハンドラを定義する構造体みたいなもの。例えば、`/proc/<pid>/sched` をシステムコール `open(2)` でファイルオープンした場合、`file_operations.open()` に登録されたハンドラが呼び出されます。
`/proc/<pid>/sched` に対する構造体名が `proc_pid_sched_operations` なので、暗黙の命名規則もありそうです。

次は、[`proc_pid_sched_operations` の中身](http://lxr.free-electrons.com/source/fs/proc/base.c?v=3.13#L1297)を見ていきます。

```:linux-3.13/fs/proc/base.c
1297 static const struct file_operations proc_pid_sched_operations = {
1298         .open           = sched_open,
1299         .read           = seq_read,
1300         .write          = sched_write,
1301         .llseek         = seq_lseek,
1302         .release        = single_release,
1303 };
```

色々なファイル操作に対して関数ポインタが代入されています。ここで追うのは `.open` に代入された `sched_open` です。

```:linux-3.13/fs/proc/base.c
1405 static int sched_open(struct inode *inode, struct file *filp)
1406 {
1407         return single_open(filp, sched_show, inode);
1408 }
```

```:linux-3.13/fs/seq_file.c
564 int single_open(struct file *file, int (*show)(struct seq_file *, void *),
565                 void *data)
566 {
567         struct seq_operations *op = kmalloc(sizeof(*op), GFP_KERNEL);
568         int res = -ENOMEM;
569 
570         if (op) {
571                 op->start = single_start;
572                 op->next = single_next;
573                 op->stop = single_stop;
574                 op->show = show;
575                 res = seq_open(file, op);
576                 if (!res)
577                         ((struct seq_file *)file->private_data)->private = data;
578                 else
579                         kfree(op);
580         }
581         return res;
582 }
583 EXPORT_SYMBOL(single_open);
```

ここで、`seq_file` の仕組みを知る必要がありますが、[「とみぞーノート：procfs を使ったカーネル情報の表示 その2」](http://wiki.bit-hive.com/tomizoo/pg/proc%20fs%20%A4%F2%BB%C8%A4%C3%A4%BF%A5%AB%A1%BC%A5%CD%A5%EB%BE%F0%CA%F3%A4%CE%C9%BD%BC%A8%20%A4%BD%A4%CE2)で詳しく説明してあるので割愛します。最終的には `sched_show()` が呼び出されることになり、ようやくスケジューリング統計情報を表示する処理が出てくることになります。

```:linux-3.13/fs/proc/base.c
1257 /*
1258  * Print out various scheduling related per-task fields:
1259  */
1260 static int sched_show(struct seq_file *m, void *v)
1261 {
1262         struct inode *inode = m->private;
1263         struct task_struct *p;
1264 
1265         p = get_proc_task(inode);
1266         if (!p)
1267                 return -ESRCH;
1268         proc_sched_show_task(p, m);
1269 
1270         put_task_struct(p);
1271 
1272         return 0;
1273 }
```

`seq_file->private` に格納していた `inode` から `get_proc_task()` で `task_struct` 構造体を持ってきています。
ここで注意することは、この一連の処理中に `task_struct` の情報が消える (例えば、タスクが `exit()` する) とNULLポインタアクセスが発生したり困ったことが発生してしまうということです。そこで、何かしら保護する仕組みが必要で、それが `get_task_struct()`, `put_task_struct()` の処理を入れることになります。
上記の `sched_show()` では、 `get_proc_task()` の延長で `get_task_struct()` を呼び出しているので、メイン処理の `proc_sched_show_task()` 実行中は、中身にアクセスしたい対象の `task_struct` が保護されていることになります。保護の仕組み自体は長くなるのでここでは割愛。

[メイン処理 `proc_sched_show_task()`](http://lxr.free-electrons.com/source/kernel/sched/debug.c?v=3.13#L553) は以下の通り。マクロを使って `printf` していますね。`CONFIG_SCHEDSTATS=y` となっていれば、豊富な情報が得られそうです。これで出力箇所がわかったので、カーネルの中身を追いかけるのはこんなところでお終い。

```:linux-3.13/kernel/sched/debug.c
553 void proc_sched_show_task(struct task_struct *p, struct seq_file *m)
554 {
555         unsigned long nr_switches;
556 
557         SEQ_printf(m, "%s (%d, #threads: %d)\n", p->comm, task_pid_nr(p),
558                                                 get_nr_threads(p));
559         SEQ_printf(m,
560                 "---------------------------------------------------------"
561                 "----------\n");
562 #define __P(F) \
563         SEQ_printf(m, "%-45s:%21Ld\n", #F, (long long)F)
564 #define P(F) \
565         SEQ_printf(m, "%-45s:%21Ld\n", #F, (long long)p->F)
566 #define __PN(F) \
567         SEQ_printf(m, "%-45s:%14Ld.%06ld\n", #F, SPLIT_NS((long long)F))
568 #define PN(F) \
569         SEQ_printf(m, "%-45s:%14Ld.%06ld\n", #F, SPLIT_NS((long long)p->F))
570 
571         PN(se.exec_start);
572         PN(se.vruntime);
573         PN(se.sum_exec_runtime);
574 
575         nr_switches = p->nvcsw + p->nivcsw;
576 
577 #ifdef CONFIG_SCHEDSTATS
578         PN(se.statistics.wait_start);

・・・（省略）・・・

653                 SEQ_printf(m, "%-45s:%21Ld\n",
654                            "clock-delta", (long long)(t1-t0));
655         }
656 
657         sched_show_numa(p, m);
658 }
```

#各統計情報の意味
分かる範囲で統計情報を以下にまとめます。Linux-3.13のソースを見て書いているので、最新カーネルでは異なっている箇所があり、その点も気づいたら追記しています。

マイグレーションやタスク起床関係の統計情報はこんなに細かいの必要？って感じのものが多いですが、実際にタスクのディスパッチ性能を気にしたり、システムの処理にどれだけ邪魔されているのか確認したい時は役に立つ時が来るかも。

| 項目 | 単位 | 意味 | 備考 |
|:---|:---|:---|:---|
| se.exec_start | ナノ秒 | タスクがCPU上で実行開始した時刻 | OS起動した時刻を 0.0 としているはず |
| se.vruntime | ナノ秒 | タスクがCPU上で実行した仮想的な時間 | 実時間を正規化（重み付け）した時間で、nice値を変更していれば実時間と異なる値になってくる (RTクラスのタスクは常に 0.0) |
| se.sum_exec_runtime | ナノ秒 | タスクがCPU上で実行した合計（実）時間 |  |
| se.statistics.wait_start | ナノ秒 | タスクがランキューから外れた状態から、ランキューに追加された時刻（**注**：本当に正しいか不安なので、もう少し調べる必要あり） | タスクがランキューから外された（デキュー）時は 0.0 になるので、スリープ中はずっと 0.0 (RTクラスのタスクは常に 0.0) |
| se.statistics.sleep_start | ナノ秒 | タスクがスリープ状態 (TASK_INTERRUPTIBLE) になった時刻 | 起床するときに 0.0 にリセットされる (RTクラスのタスクは常に 0.0) |
| se.statistics.block_start | ナノ秒 | タスクがブロック状態 (TASK_UNINTERRUPTIBLE) になった時刻 | (RTクラスのタスクは常に 0.0) |
| se.statistics.sleep_max | ナノ秒 | タスクがスリープ状態 (TASK_INTERRUPTIBLE) となっていた最長時間 |  (RTクラスのタスクは常に 0.0) |
| se.statistics.block_max | ナノ秒 | タスクがブロック状態 (TASK_UNINTERRUPTIBLE) となっていた最長時間 |  (RTクラスのタスクは常に 0.0) |
| se.statistics.exec_max | ナノ秒 | タスクがCPU上で実行していた最長時間 |  |
| se.statistics.slice_max | ナノ秒 | 前回の実行時間最大値と現在の実行時間最大値 (`sum_exec_runtime`) との差分 | ランキューの負荷がタスクの負荷の２倍以上になった時だけ `slice_max` を更新しようとする (RTクラスのタスクは常に 0.0) |
| se.statistics.wait_max | ナノ秒 | タスクがランキューから外れていた最大時間（**注**：本当に正しいか不安なので、もう少し調べる必要あり） |  (RTクラスのタスクは常に 0.0) |
| se.statistics.wait_sum | ナノ秒 | タスクがランキューから外れていた合計時間（**注**：本当に正しいか不安なので、もう少し調べる必要あり） |  (RTクラスのタスクは常に 0.0) |
| se.statistics.wait_count | 回数 | タスクがランキューから外れた回数 |  |
| se.statistics.iowait_sum | ナノ秒 | タスクがI/O待ち状態になっている合計時間 | カーネルの中身としては、`io_schedule()` を呼び出してスリープした時から再びランキューに追加（エンキュー）される時までがアカウンティングされる |
| se.statistics.iowait_count | 回数 | タスクがI/O待ち状態になった回数 |  |
| se.nr_migrations | 回数 | タスクが実行されるCPUを移動した回数 |  |
| se.statistics.nr_migrations_cold | 回数 | ?? | 現在使われていないみたいです |
| se.statistics.nr_failed_migrations_affine | 回数 | マイグレーションしようとしたが、タスクのアフィニティマスクに移動先のCPUが含まれていないためにマイグレーション失敗した回数 |  |
| se.statistics.nr_failed_migrations_running | 回数 | マイグレーションしようとしたが、タスクが実行中であるためにマイグレーション失敗した回数 |  |
| se.statistics.nr_failed_migrations_hot | 回数 | マイグレーションしようとしたが、タスクがキャッシュホットと判定されたためにマイグレーション失敗した回数 | `sysctl` コマンドにより `sched_migration_cost` を設定することで、キャッシュホットの判定基準を変更可能 ([`sched_migration_cost` の説明は OpenSUSE のページ参照](http://manual.geeko.cpon.org/ja/cha.tuning.taskscheduler.html)) |
| se.statistics.nr_forced_migrations | 回数 | タスクが無理やりマイグレーションされた回数 | 今までスケジュールドメインレベルのマイグレーションの失敗回数が多い場合、キャッシュホットであるにも関わらずマイグレーションされることがある |
| se.statistics.nr_wakeups | 回数 | タスクがスリープキューから起床した回数 |  |
| se.statistics.nr_wakeups_sync | 回数 | ?? | 2.6系カーネルでは関数 `__wake_up_sync()` を通ったらカウントされてたみたいだけど、3.13系以降では見当たらない。 |
| se.statistics.nr_wakeups_migrate | 回数 | タスク起床時に元いたCPUとは異なるCPUのランキューにつなげられた回数 |  |
| se.statistics.nr_wakeups_local | 回数 | タスクを起床させたCPUが、そのタスクが起床予定のCPUと同じだった回数 |  |
| se.statistics.nr_wakeups_remote | 回数 | タスクを起床させたCPUが、そのタスクが起床予定のCPUと異なっていた回数 |  |
| se.statistics.nr_wakeups_affine | 回数 | タスクが自分のCPUで起床した回数（？） | これはもう少しちゃんとソース読まないと分からない |
| se.statistics.nr_wakeups_affine_attempts | 回数 | タスクが自分のCPUで起床しようとした回数（？） | 同上 |
| se.statistics.nr_wakeups_passive | 回数 | ?? | 2.6系カーネルではスケジュールドメイン内のロードバランスにより受動的に負荷分散のためにCPUが選択されるらしいが、よく分かっていない。今は使われてなさそうなので、深く追いかけるのはやめる。 |
| se.statistics.nr_wakeups_idle | 回数 | ?? | 2.6系カーネルでは関数 `wake_idle()` で選択した起床先のCPUがアイドル状態であればカウントされていた。現在特に意味はないようだ。 |
| avg_atom | ナノ秒 | １回コンテキストスイッチが行われる間にタスクを実行した平均時間 | `sum_exec_runtime` を `nr_switches` で割った値が入る。もし、`nr_switches == 0` なら -1 となる。 |
| avg_per_cpu | ナノ秒 | １つのCPU上で実行された平均時間 | `sum_exec_runtime` を `nr_migrations` で割った値が入る。もし、`nr_migrations == 0` なら -1 となる。 |
| nr_switches | 回数 | コンテキストスイッチをした回数 | `nr_voluntary_switches` と `nr_involuntary_switches` の合計値 |
| nr_voluntary_switches | 回数 | 自発的なコンテキストスイッチの回数 | [タスクスケジューラのカウンタ](http://qiita.com/hikanda/items/b6d35ed3ffa3a2eddcc1) にも少し説明を書きました。でも、今の最新のカーネル (Linux-4.6系) みるとプリエンプションしているか否かで voluntary か involuntary を決めてるみたいです。 |
| nr_involuntary_switches | 回数 | 非自発的なコンテキストスイッチの回数 | 同上 |
| se.load.weight | 整数値 | 優先度に応じた重み | [kernel/sched/sched.h の配列 `prio_to_weight` にnice値に応じた重みが定義](http://lxr.free-electrons.com/source/kernel/sched/sched.h?v=3.13#L955)されている |
| se.avg.runnable_avg_sum | ?? | ?? | どうやら過去のスケジューリング情報を元に重み計算しているようだがよく分からない。どうせこんな細かい所はすぐ修正されるだろうなと思ったら、やっぱり [linux-4.6 で跡形も無く消えてた](http://lxr.free-electrons.com/source/kernel/sched/fair.c?v=4.6)。とは言え、また似たような別の仕組みになってるので後で勉強しよ。 |
| se.avg.runnable_avg_period | ?? | ?? | 同上 |
| se.avg.load_avg_contrib | ?? | ?? | 同上 |
| se.avg.decay_count | ?? | ?? | 同上 |
| policy | 数値 | スケジューリングポリシー | どんなポリシーがあるかは [`include/uapi/linux/sched.h` に定義してある "Scheduling policies" を確認してください](http://lxr.free-electrons.com/source/include/uapi/linux/sched.h?v=3.13#L33) |
| prio | 0〜139の値 | タスクの優先度 | RTタスクは 0 〜 99、CFSクラスは 100 〜 139 の値。nice値は -20 〜 19 の範囲で動かせるが、CFSクラスの優先度デフォルト値が 120 なので、`120 + nice` がカーネル内で使われる (CFSクラスの) タスクの優先度。 |
| clock-delta | ナノ秒 | タスクが動作しているCPU上で、連続して `cpu_clock()` を呼び出した時の時間差 | CPUアーキテクチャ依存。なんのためにこんな時間計測してるんだろうか。 |