概要

vmstatコマンドなどでユーザー時間、システム時間、IO要求待ち時間、アイドル時間に相当する項目を見てシステムのボトルネックを調査したりしますが、そもそもこの値ってどうやってカーネルで計測しているんだろう〜と思っていました。そんな時にサーバー/インフラを支える技術という本にこの疑問に答えてくれる記述があり、その箇所について自分なりに深掘りしたときのメモです。

全体的に知識不足なので内容に関して間違っていること激高です。その場合はご容赦下さい。

読んだ本

[24時間365日] サーバ/インフラを支える技術 ‾スケーラビリティ、ハイパフォーマンス、省力運用 (WEB+DB PRESS plusシリーズ)

環境

$ uname -r
2.6.32-642.6.2.el6.x86_64

$ cat /etc/redhat-release 
CentOS release 6.8 (Final)

自分の環境が上記なので、とりあえずstableリポジトリにあった2.6.32の2.6.32.71を対象に深掘りしてみました。

プロセスアカウンティング

本によるとカーネルは各プロセスが生成されてからどの程度CPU時間を利用したかをプロセスごとに記録しているそうです。そしてその記録している処理をプロセスアカウンティングと呼んでいて、その始まりがkernel/timer.cの中にあるupdate_process_times()ということでした。

各プロセスのユーザー時間、システム時間、IO要求待ち時間、アイドル時間はupdate_process_times()から始まる処理で統計が取られており、vmstatなどのコマンドはこの情報を取得して表示している前提で進めます。

update_process_times()

それでは上記の環境でupdate_process_times()を探してみます。

$ grep -rn update_process_times ./kernel
./kernel/timer.c:1208:void update_process_times(int user_tick)
./kernel/tags:10861:update_process_times        timer.c /^void update_process_times(int user_tick)$/;"  f
./kernel/time/tick-common.c:72: update_process_times(user_mode(get_irq_regs()));
./kernel/time/tick-sched.c:559:  * time we slept as update_process_times does only a 1 tick
./kernel/time/tick-sched.c:628: update_process_times(user_mode(regs));
./kernel/time/tick-sched.c:788:         update_process_times(user_mode(regs));

本と同じくkernel/timer.cの中にあるようです。

調査したカーネルが本のカーネルのバージョンと違うので多少コードが違っています。(本ではカーネルバージョンは書かれてなかったです。たぶん。)気にせずにupdate_process_times()を見てみます。

kernel/timer.c

/*
 * Called from the timer interrupt handler to charge one tick to the current
 * process.  user_tick is 1 if the tick is user time, 0 for system.
 */
void update_process_times(int user_tick)
{
        struct task_struct *p = current;
        int cpu = smp_processor_id();

        /* Note: this timer irq context must be accounted for as well. */
        account_process_tick(p, user_tick);
        run_local_timers();
        rcu_check_callbacks(cpu, user_tick);
        printk_tick();
        scheduler_tick();
        run_posix_cpu_timers(p);
}

account_process_tick()が本でも紹介されているプロセスアカウンティングの中心のようです。account_process_tick()をみていきます。

account_process_tick()

kernel/shced.c

 /*
 * Account a single tick of cpu time.
 * @p: the process that the cpu time gets accounted to
 * @user_tick: indicates if the tick is a user or a system tick
 */
void account_process_tick(struct task_struct *p, int user_tick)
{
        cputime_t one_jiffy_scaled = cputime_to_scaled(cputime_one_jiffy);
        struct rq *rq = this_rq();

        if (user_tick)
                account_user_time(p, cputime_one_jiffy, one_jiffy_scaled);
        else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))
                account_system_time(p, HARDIRQ_OFFSET, cputime_one_jiffy,
                                    one_jiffy_scaled);
        else
                account_idle_time(cputime_one_jiffy);
}

前提

this_rq()
- ローカルCPUの実行キューのアドレスを取得します。取得した実行キューにはTASK_RUNNNINGのプロセスしか存在しない。よって、IO待ちで待機しているプロセスやスリープしているプロセスはこの実行キューには存在しない。ただし、例外としてswapperプロセス(idleプロセス)は存在する。
rq->idle
- ローカルCPUのswapperプロセスのプロセスディスクリプタへのポインタ
swapperプロセス
- アイドルプロセスのこと
- swapperプロセスとは
- カレントプロセスがswapperプロセスということはthis_rq()で取得するランキュー上にはTASK_RUNNNINGのプロセスは存在しない。

ここでユーザー時間、システム時間、アイドル時間(IO要求待ち時間含む)の各処理に分岐します。どのような条件でプロセスの時間が割り当てられ統計が取られていくのかを見ていきます。

ユーザー時間の統計

user_tickは直近のプロセスが動いている時間がユーザー時間だったのか、システム時間であったのかを判定するフラグのようです。これがユーザー時間のフラグであれば、account_user_time()の中でユーザー時間として計測されます。

システム時間の統計

システム時間として計測される条件

kernel/shced.c

        else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))
                account_system_time(p, HARDIRQ_OFFSET, cputime_one_jiffy,
                                    one_jiffy_scaled);

① p != rq->idle

p != rq->idle

カレントプロセスがswapperプロセス(idleプロセス)でない場合にtrue。直近の時間がユーザ時間ではなくてカレントプロセスがTASK_RUNNNINGなプロセスの場合はシステム時間として計測されるようです。

② irq_count() != HARDIRQ_OFFSET

本では記載が無かった条件(irq_count() != HARDIRQ_OFFSET)が追加されています。

気になったのでgitで該当箇所のコミットを探してコミットメッセージを見てみました。

$ git show f5f293a4
commit f5f293a4e3d0a0c52cec31de6762c95050156516
Author: Eric Dumazet <dada1@cosmosbay.com>
Date:   Wed Apr 29 14:44:49 2009 +0200

    sched: account system time properly
    
    Andrew Gallatin reported that IRQ and SOFTIRQ times were
    sometime not reported correctly on recent kernels, and even
    bisected to commit 457533a7d3402d1d91fbc125c8bd1bd16dcd3cd4
    ([PATCH] fix scaled & unscaled cputime accounting) as the first
    bad commit.
    
    Further analysis pointed that commit
    79741dd35713ff4f6fd0eafd59fa94e8a4ba922d ([PATCH] idle cputime
    accounting) was the real cause of the problem.
    
    account_process_tick() was not taking into account timer IRQ
    interrupting the idle task servicing a hard or soft irq.
    
    On mostly idle cpu, irqs were thus not accounted and top or
    mpstat could tell user/admin that cpu was 100 % idle, 0.00 %
    irq, 0.00 % softirq, while it was not.
    
    [ Impact: fix occasionally incorrect CPU statistics in top/mpstat ]
    
    Reported-by: Andrew Gallatin <gallatin@myri.com>
    Re-reported-by: Andrew Morton <akpm@linux-foundation.org>
    Signed-off-by: Eric Dumazet <dada1@cosmosbay.com>
    Acked-by: Martin Schwidefsky <schwidefsky@de.ibm.com>
    Cc: rick.jones2@hp.com
    Cc: brice@myri.com
    Cc: Paul Mackerras <paulus@samba.org>
    Cc: Benjamin Herrenschmidt <benh@kernel.crashing.org>
    LKML-Reference: <49F84BC1.7080602@cosmosbay.com>
    Signed-off-by: Ingo Molnar <mingo@elte.hu>

diff --git a/kernel/sched.c b/kernel/sched.c
index b902e58..26efa47 100644
--- a/kernel/sched.c
+++ b/kernel/sched.c
@@ -4732,7 +4732,7 @@ void account_process_tick(struct task_struct *p, int user_tick)
 
        if (user_tick)
                account_user_time(p, one_jiffy, one_jiffy_scaled);
-       else if (p != rq->idle)
+       else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))
                account_system_time(p, HARDIRQ_OFFSET, one_jiffy,
                                    one_jiffy_scaled);
        else

恐らく、コミットメッセージから推測するにaccount_process_tick()はタイマ割り込みがswapperプロセスを中断するときを考慮していなかったようです。account_system_time()の先で割り込みに関する情報も足し込んでおりこの条件を入れることでswapperプロセスの場合でも割り込みの時間を考慮するようになるのではないでしょうか。

account_system_time()全体

kernel/shced.c

/*
 * Account system cpu time to a process.
 * @p: the process that the cpu time gets accounted to
 * @hardirq_offset: the offset to subtract from hardirq_count()
 * @cputime: the cpu time spent in kernel space since the last update
 * @cputime_scaled: cputime scaled by cpu frequency
 */
void account_system_time(struct task_struct *p, int hardirq_offset,
                         cputime_t cputime, cputime_t cputime_scaled)
{
        struct cpu_usage_stat *cpustat = &kstat_this_cpu.cpustat;
        cputime64_t tmp;

・
・
・
        /* Add system time to cpustat. */
        tmp = cputime_to_cputime64(cputime);
        if (hardirq_count() - hardirq_offset)
                cpustat->irq = cputime64_add(cpustat->irq, tmp);
        else if (in_serving_softirq())
                cpustat->softirq = cputime64_add(cpustat->softirq, tmp);
        else
                cpustat->system = cputime64_add(cpustat->system, tmp);

        cpuacct_update_stats(p, CPUACCT_STAT_SYSTEM, cputime);

        /* Account for system time used */
        acct_update_integrals(p);
}

割り込み処理時間を考慮する必要がある場合には割り込み時間に足しこんで、その必要が無くTASK_RUNNNINGなプロセスの場合はシステム時間として計測されるようです。

I/O wait時間、idle時間の統計

account_process_tick()に戻って見てみます。

kernel/shced.c

 /*
 * Account a single tick of cpu time.
 * @p: the process that the cpu time gets accounted to
 * @user_tick: indicates if the tick is a user or a system tick
 */
void account_process_tick(struct task_struct *p, int user_tick)
{
        cputime_t one_jiffy_scaled = cputime_to_scaled(cputime_one_jiffy);
        struct rq *rq = this_rq();

        if (user_tick)
                account_user_time(p, cputime_one_jiffy, one_jiffy_scaled);
        else if ((p != rq->idle) || (irq_count() != HARDIRQ_OFFSET))
                account_system_time(p, HARDIRQ_OFFSET, cputime_one_jiffy,
                                    one_jiffy_scaled);
        else
                account_idle_time(cputime_one_jiffy);
}

account_idle_time()を呼び出す時のカレントプロセスはswapperプロセスになるかと思われます。ということは、カレントプロセスがユーザープロセスではなく、swapperプロセスであり、割り込み処理に関する考慮が必要でない場合にaccount_idle_time()に処理を移します。account_idle_time()を見ていきます。

account_idle_time()

kernel/shced.c

/*
 * Account for idle time.
 * @cputime: the cpu time spent in idle wait
 */
void account_idle_time(cputime_t cputime)
{
        struct cpu_usage_stat *cpustat = &kstat_this_cpu.cpustat;
        cputime64_t cputime64 = cputime_to_cputime64(cputime);
        struct rq *rq = this_rq();

        if (atomic_read(&rq->nr_iowait) > 0)
                cpustat->iowait = cputime64_add(cpustat->iowait, cputime64);
        else
                cpustat->idle = cputime64_add(cpustat->idle, cputime64);
}

前提

&rq->nr_iowait
- もともとこの実行キューリスト上にいて、現在はディスクI/O操作の完了を待っているプロセス数のこと

I/O wait時間の統計

カレントプロセスがswapperプロセスの場合に(TASK_RUNNNINGなプロセスが存在しない場合)、IO待ちのプロセスが一つでも存在すればIOwait時間として足し込まれます。

idle時間の統計

カレントプロセスがswapperプロセスの場合(TASK_RUNNNINGなプロセスが存在しない場合)に、IOwaitのプロセスが一つでも存在しない場合、idle時間として足し込まれます。

色々試してみる

調べた結果とコマンドの挙動が感覚的にあっているか知りたかったので色々試してみました。

前提

以下で各プロセス状態を作成する。

R(TASK_RUNNING): phpで無限ループを実行

test.php

<?php
while(true){
}

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root      9123  9123 94.6    1  0.7 210204  7148 pts/3    R+   00:01   0:18 php test.php

D(TASK_UNINTERRUPTIB): dd if=/dev/zero of=test bs=100M count=512

root      8091  8091  0.0    1  0.0      0     0 ?        D    Jan19   0:00 [flush-253:1]
root      9528  9528  6.8    1 10.1 207596 103120 pts/0   D+   00:03   0:01 dd if=/dev/zero of=test bs=100M count=512

この２つを用いて意図的にプロセス状態R(TASK_RUNNING)とD(TASK_UNINTERRUPTIB)を作って色々試してみる。

D(TASK_UNINTERRUPTIB)プロセスあり

何もしていない状態からD(TASK_UNINTERRUPTIB)なプロセスを増やしてみます。

ddコマンド実行

dd if=/dev/zero of=test bs=100M count=512

別の端末でVMSTAT実行確認

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0    187      7    728    0    0     0     0  860   31  0  0 100  0  0 
 0  0      0    187      7    728    0    0     0     0  832   34  1  1 98  0  0 
 0  2      0    579      7    238    0    0     8 61760 1105   87  0 22 71  6  1 
 1  2      0    465      7    347    0    0     0 122184 1111  265  1  9  0 90  0 
 0  2      0    356      7    452    0    0     0 116940  855  283  0  8  0 92  0 
 2  2      0    294      7    519    0    0     0 67544  605  148  0 10  0 90  0 
 0  2      0    149      7    653    0    0     0 126236  606  157  1 15  0 82  1 
 1  2      0     72      7    728    0    0     0 113608  969  316  0  9  0 91  0 
 0  4      0     72      7    728    0    0   224 98280  878  429  0  8  0 91  1 
 0  2      0     73      7    726    0    0   196 83668 1076  470  1 10  0 88  1

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     11795 11795  3.1    1  0.0      0     0 ?        D    02:47   0:01 [flush-253:1]
root     11821 11821 10.4    1 10.1 207596 103124 pts/0   D+   02:48   0:02 dd if=/dev/zero of=test bs=100M count=512

Dの状態が増えたタイミングで、idleが0になり、waの値が増えました。これは「カレントプロセスがswapperプロセスの場合に(TASK_RUNNNINGなRなプロセスが存在しない場合)、IO待ちのプロセスが一つでも存在すればIOwait時間として足し込まれる」に合致します。idle時間に足し込まれなくなり、IOwait時間に足しこまれたんだと思います。

R(TASK_RUNNING)なプロセスあり

何もしていない状態からR(TASK_RUNNING)なプロセスを増やしてみます。

phpで無限ループを実行

test.php

<?php
while(true){
}

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root     31265 31265 66.8    1  0.7 210204  7148 pts/3    R+   04:15   0:04 php test.php

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0    186      7    728    0    0     1    75  164    5  0  0 100  0  0 
 0  0      0    186      7    728    0    0     0     0   56   31  1  0 99  0  0 
 0  0      0    186      7    728    0    0     0     0   52   34  0  1 99  0  0 
 0  0      0    186      7    728    0    0     0     0   41   33  1  0 99  0  0 
 0  0      0    186      7    728    0    0     0     0   53   38  0  1 99  0  0 
 0  0      0    186      7    728    0    0     0     0   50   30  0  1 99  0  0 
 1  0      0    182      7    730    0    0  1772     0  486  133 38  0 23 38  0 
 1  0      0    181      7    730    0    0     0     0 1018   46 99  1  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1017   35 100  0  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1014   39 99  1  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1016   37 100  0  0  0  0 
 1  0      0    182      7    730    0    0     0     0 1015   37 99  1  0  0  0 
 1  0      0    182      7    730    0    0     0    44 1021   50 100  0  0  0  0 
 1  0      0    182      7    730    0    0     0     0 1013   37 100  0  0  0  0 
・
・
・
 1  0      0    182      7    730    0    0     0     0 1016   39 99  1  0  0  0 
 1  0      0    182      7    730    0    0     0     0 1020   36 100  0  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1013   38 99  1  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1015   36 99  1  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1017   36 99  0  0  0  1 
 1  0      0    181      7    730    0    0     0    36 1017   41 99  1  0  0  0 
 1  0      0    181      7    730    0    0     0     0 1015   37 99  0  0  0  1 
 0  0      0    185      7    730    0    0     0     0  629   44 60  1 39  0  0 
 0  0      0    185      7    730    0    0     0     0   47   35  1  0 99  0  0 
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0    185      7    730    0    0     0     0   51   36  0  1 99  0  0 
 0  0      0    185      7    730    0    0     0     0   52   32  1  1 98  0  0 
 0  0      0    184      7    730    0    0     0     0   46   31  0  0 100  0  0 
 0  0      0    184      7    730    0    0     0     0   44   30  0  1 99  0  0 
 0  0      0    184      7    730    0    0     0     0   49   29  0  1 99  0  0 
 0  0      0    184      7    730    0    0     0     0   45   34  1  0 99  0  0

phpを実行したタイミング(Rプロセス生成)でidleは0％になりました。そのタイミングからユーザー時間に足し込まれれていると思います。プログラムはは無限ループなのでpsコマンドではずっとRの状態で確認できます。プログラムの実行を中断するとidleが100%になります。ユーザー空間で完結しているのでusの値が高くなっています。

R(TASK_RUNNING)なプロセスとD(TASK_UNINTERRUPTIB)なプロセス混在

最後に R(TASK_RUNNING)とD(TASK_UNINTERRUPTIB)を混在させます。
初めにDなプロセスを生成して、次にRなプロセスを生成します。

RとDを確認

USER       PID   LWP %CPU NLWP %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root       452   452  0.0    1  0.0      0     0 ?        D    Jan17   0:01 [jbd2/dm-1-8]
root     32549 32549  1.7    1  0.0      0     0 ?        D    04:24   0:00 [flush-253:1]
root     32640 32640  5.2    1 10.1 207596 103124 pts/0   D+   04:25   0:01 dd if=/dev/zero of=test bs=100root     32681 32681 66.8    1  0.7 210204  7148 pts/3    R+   04:25   0:12 php test.php

何もない状態からDなプロセスを生成したタイミングでwaの値が増えます。Rがなく、DがあるのでIOwait時間に足し込まれるからです。次に、この状態でRなプロセスを生成するとwaの値は減り、usの値が増えます。waの値が減るのはDなプロセス(IO要求待ち)が存在しても、Rなプロセスがあるとユーザー時間かシステム時間に足し込まれるからです。これも調査した結果と合致します。IO中なのでioの値はそのまま遷移しています。

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0    187      7    727    0    0     1    78  166    5  0  0 100  0  0 
 0  0      0    187      7    727    0    0     0     0  727   34  0  1 99  0  0 
 0  0      0    187      7    727    0    0     0     0  875   36  1  1 97  0  1 
 0  0      0    187      7    727    0    0     0    28  802   45  0  0 90 10  0 
 0  0      0    187      7    727    0    0     0     0  692   31  0  2 98  0  0 
 0  0      0    187      7    727    0    0     0     0  752   33  0  1 99  0  0 
 0  0      0    187      7    727    0    0     0     0  884   32  1  1 97  0  1 
 0  0      0    187      7    727    0    0     0     0  684   36  0  0 100  0  0 
 0  0      0    187      7    727    0    0     0     0  794   32  0  1 99  0  0 
 0  0      0    187      7    727    0    0     0     0  631   35  1  0 99  0  0 
 1  0      0    228      7    687    0    0    72     0  671   56  0  1 96  2  1 
 0  2      0    517      7    296    0    0     0 133880 1106  186  0 27  0 73  0 
 0  2      0    430      7    380    0    0     4 93456 1019  201  0  8  0 92  0 
 0  1      0    367      7    442    0    0     4 59500  934  179  1  5  0 93  1 
 0  2      0    280      7    526    0    0     4 93388 1069  156  0  7  0 93  0 
 0  2      0    175      7    627    0    0     4 98800  717  151  1  9  0 90  0 
 0  3      0     95      7    707    0    0     0 69020  775  242  0  8  0 92  0 
 0  4      0     73      7    726    0    0   104 103228  805  242  0  8  0 91  1 
 0  2      0     71      7    730    0    0   316 82656  926  372  0  9  0 91  0 
 0  2      0     73      7    727    0    0     0 103824 1002  259  1  8  0 91  0 
 0  2      0     72      7    727    0    0     0 121272  972  273  0 10  0 90  0 
 0  3      0     65      7    735    0    0     0 53964 1098  265  0  5  0 94  1 
 0  4      0     69      7    731    0    0   416 94752 1066  542  1  7  0 92  0 
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  3      0     73      7    728    0    0   536 64520 1131  367  0  7  0 92  1 
 0  3      0     69      7    729    0    0   576 106344 1041  377  0  8  0 92  0 
 1  5      0     70      7    726    0    0   796 83664  947  354  3  8  0 88  1 
 1  3      0     62      7    735    0    0   104 74624 1980  305 93  7  0  0  0 
 1  3      0     71      7    727    0    0     0 97272 1644  286 89 11  0  0  0 
 1  2      0     72      7    726    0    0     0 107860 1693  226 91  9  0  0  0 
 1  2      0     73      7    724    0    0     0 121980 1915  203 90 10  0  0  0 
 1  2      0     70      7    727    0    0     0 111384 2049  215 86 14  0  0  0 
 2  2      0     70      7    727    0    0     0 79348 1922  275 92  8  0  0  0 
 2  2      0     66      7    731    0    0    72 106128 1584  425 86 14  0  0  0 
 1  3      0     73      7    724    0    0   316 36428 1550  230 96  4  0  0  0 
 1  2      0     65      7    732    0    0    32 87696 1568  337 92  8  0  0  0 
 1  2      0     74      7    723    0    0     0 58968 1660  184 95  5  0  0  0 
 1  1      0     70      7    727    0    0     0 19656 1615  100 96  4  0  0  0 
 1  3      0     65      7    732    0    0     0 71100 1986  293 92  8  0  0  0 
 1  3      0     73      7    725    0    0     0 35296 1695  202 95  5  0  0  0 
 1  3      0     65      7    732    0    0     0 104836 1623  220 92  8  0  0  0 
 1  2      0     72      7    726    0    0     0 105840 1642  232 90 10  0  0  0 
 1  1      0     75      7    724    0    0     0 66284 1795  164 90 10  0  0  0 
 1  3      0     65      7    732    0    0    72 103108 1812  517 88 12  0  0  0 
 1  4      0     69      7    727    0    0   316 68544 1689  297 92  8  0  0  0 
 0  2      0     75      7    725    0    0    32 48956 1966  243 95  4  0  1  0 
 0  2      0     74      7    727    0    0     0 49528  928 7399  1  3  0 95  1 
procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  2      0     73      7    727    0    0     0 40824  834 6039  0  3  0 97  0 
 0  2      0     80      7    727    0    0     0  8608 1067  117  0  1  0 99  0 
 0  0      0    187      7    727    0    0     0  3596  774   67  1  0 36 63  0 
 0  0      0    187      7    727    0    0     0     0  886   32  1  1 97  0  1 
 0  0      0    187      7    727    0    0     0     0  824   33  0  0 100  0  0 
 0  0      0    187      7    727    0    0     0     0 1054   34  1  0 99  0  0 
 0  0      0    187      7    727    0    0     0     0 1140   33  0  1 98  0  1 
 0  0      0    187      7    727    0    0     0    24 1045   44  1  0 95  4  0 
 0  0      0    187      7    727    0    0     0     0  682   32  0  1 99  0  0 
 0  0      0    187      7    727    0    0     0     0  783   32  0  1 99  0  0 
 0  0      0    187      7    727    0    0     0     0  946   35  1  0 99  0  0

考察

IO待ちが多い
- vmstatコマンドでみるとwaが高い状況です(bも高くなる)。この状況は他にR(TASK_RUNNING)なプロセスが存在せずCPUが空いている状況で、D(TASK_UNINTERRUPTIB)プロセスが存在しているということです。何かしらシステムに不具合がある場合はIOがボトルネックになっている場合があるはずです。ただ、CPUは空いている状態なのでIOwaitが98%であってもCPUの負荷が高い状態ではないといえるはずです。
- ただし、RなプロセスがCPUを使用するとwa(IO時間)は減少しますが、IO待ちのプロセスが無くなったわけではない。
idle時間が多い
- vmstatコマンドでみるとidleが高い状況です。R(TASK_RUNNING)なプロセスなし、D(TASK_UNINTERRUPTIB)プロセスもない、CPUが空いている状況を示しています。スリープしているプロセスがたくさんいるんだと思います。
CPU負荷が高い
- us + syの値が100%近く。syの方が高いとIOがボトルネックになっている場合もある。
- LAが高いということ
  - R(TASK_RUNNING)とD(TASK_UNINTERRUPTIB)のプロセスが通常より多くいる
- この状況下で
  - R(TASK_RUNNING)が多い場合、D(TASK_UNINTERRUPTIB)プロセスがたくさん存在していてもwaには反映されない。~~が、不具合がない限りRの状態がずっと続くことは少なそうなのでDがたくさんいた場合は、waに反映されそう~~。なのでこの場合、IO待ちの具合を調べるのはb列を確認するのが確実そう。ただ、waの値が高い状態は、そのまま単純にIO待ちが多いということを表している。
  - D(TASK_UNINTERRUPTIB)に比べてR(TASK_RUNNING)が多い場合usとsyが高いはず。
  - R(TASK_RUNNING)に比べてD(TASK_UNINTERRUPTIB)が多い場合、LA高いけど、waは低い、usとsyもそれなり。
  - CPUの負荷がかかっていない(us + syの値が100%近く無い)のにロードアベレージが上昇している場合には、I/Oがボトルネックになっている場合がある(まぁwaの値などを見ればよいのか)。

処理内容を実際にコードレベルで垣間見ることで考えに根拠を持つことができました。

最後に

日頃からカーネルがどういった動きをしているのか興味があり、疑問に思ったことから実際に自分なりにカーネルを追ってみました。分からないことはとても多いですがこれからも興味あるところから少しずつ読んでみたい思います。そしてこの経験がいつかどこかに繋がっていけば・・。

参考