Help us understand the problem. What is going on with this article?

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

More than 3 years have passed since last update.

/proc/<pid>/sched の中身

procのmanマニュアルに書いてなかったので今まで全然気づいていなかったんですが、便利なスケジューリング統計情報をユーザが簡単に見れることを最近知りました。/proc/<pid>/sched です。

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

$ 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 を見てみましょう。

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 に書いてます。ファイルのアクセス権を変更する chmod コマンドで引数に渡す mode と同じ感じですし、stat(2) の man マニュアルにも書いてくれてます
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 構造体を指定してて、これはファイルの操作に対するハンドラを定義する構造体みたいなもの。例えば、/proc/<pid>/sched をシステムコール open(2) でファイルオープンした場合、file_operations.open() に登録されたハンドラが呼び出されます。
/proc/<pid>/sched に対する構造体名が proc_pid_sched_operations なので、暗黙の命名規則もありそうです。

次は、proc_pid_sched_operations の中身を見ていきます。

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」で詳しく説明してあるので割愛します。最終的には 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() は以下の通り。マクロを使って 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) との差分 ランキューの負荷がタスクの負荷の2倍以上になった時だけ 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 ナノ秒 1回コンテキストスイッチが行われる間にタスクを実行した平均時間 sum_exec_runtimenr_switches で割った値が入る。もし、nr_switches == 0 なら -1 となる。
avg_per_cpu ナノ秒 1つのCPU上で実行された平均時間 sum_exec_runtimenr_migrations で割った値が入る。もし、nr_migrations == 0 なら -1 となる。
nr_switches 回数 コンテキストスイッチをした回数 nr_voluntary_switchesnr_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アーキテクチャ依存。なんのためにこんな時間計測してるんだろうか。
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
Comments
No comments
Sign up for free and join this conversation.
If you already have a Qiita account
Why do not you register as a user and use Qiita more conveniently?
You need to log in to use this function. Qiita can be used more conveniently after logging in.
You seem to be reading articles frequently this month. Qiita can be used more conveniently after logging in.
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away
ユーザーは見つかりませんでした