/proc/<pid>/sched の中身
procのmanマニュアルに書いてなかったので今まで全然気づいていなかったんですが、便利なスケジューリング統計情報をユーザが簡単に見れることを最近知りました。/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 を見てみましょう。
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 に書いてます。ファイルのアクセス権を変更する chmod コマンドで引数に渡す mode と同じ感じですし、stat(2) の man マニュアルにも書いてくれてます。
ls -l /proc/<pid> を実行した結果とtgid_base_stuff のメンバとを比較すると、設定通りにアクセス権が反映されていることがわかります。
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 構造体を指定してて、これはファイルの操作に対するハンドラを定義する構造体みたいなもの。例えば、/proc/<pid>/sched をシステムコール open(2) でファイルオープンした場合、file_operations.open() に登録されたハンドラが呼び出されます。
/proc/<pid>/sched に対する構造体名が proc_pid_sched_operations なので、暗黙の命名規則もありそうです。
次は、proc_pid_sched_operations の中身を見ていきます。
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 です。
1405 static int sched_open(struct inode *inode, struct file *filp)
1406 {
1407 return single_open(filp, sched_show, inode);
1408 }
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」で詳しく説明してあるので割愛します。最終的には sched_show() が呼び出されることになり、ようやくスケジューリング統計情報を表示する処理が出てくることになります。
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() は以下の通り。マクロを使って printf していますね。CONFIG_SCHEDSTATS=y となっていれば、豊富な情報が得られそうです。これで出力箇所がわかったので、カーネルの中身を追いかけるのはこんなところでお終い。
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 のページ参照) |
| 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 | 回数 | 自発的なコンテキストスイッチの回数 | タスクスケジューラのカウンタ にも少し説明を書きました。でも、今の最新のカーネル (Linux-4.6系) みるとプリエンプションしているか否かで voluntary か involuntary を決めてるみたいです。 |
| nr_involuntary_switches | 回数 | 非自発的なコンテキストスイッチの回数 | 同上 |
| se.load.weight | 整数値 | 優先度に応じた重み |
kernel/sched/sched.h の配列 prio_to_weight にnice値に応じた重みが定義されている |
| se.avg.runnable_avg_sum | ?? | ?? | どうやら過去のスケジューリング情報を元に重み計算しているようだがよく分からない。どうせこんな細かい所はすぐ修正されるだろうなと思ったら、やっぱり linux-4.6 で跡形も無く消えてた。とは言え、また似たような別の仕組みになってるので後で勉強しよ。 |
| se.avg.runnable_avg_period | ?? | ?? | 同上 |
| se.avg.load_avg_contrib | ?? | ?? | 同上 |
| se.avg.decay_count | ?? | ?? | 同上 |
| policy | 数値 | スケジューリングポリシー | どんなポリシーがあるかは include/uapi/linux/sched.h に定義してある "Scheduling policies" を確認してください
|
| prio | 0〜139の値 | タスクの優先度 | RTタスクは 0 〜 99、CFSクラスは 100 〜 139 の値。nice値は -20 〜 19 の範囲で動かせるが、CFSクラスの優先度デフォルト値が 120 なので、120 + nice がカーネル内で使われる (CFSクラスの) タスクの優先度。 |
| clock-delta | ナノ秒 | タスクが動作しているCPU上で、連続して cpu_clock() を呼び出した時の時間差 |
CPUアーキテクチャ依存。なんのためにこんな時間計測してるんだろうか。 |