iostat はどのように %util を算出しているか(3)

と続いた iostat から Linux Kernel のブロックレイヤーへの旅は

のおかげでほぼ終わりを迎えました。

part_round_stats() では、その延長で、全てのリクエストがキューにいた時間の積算値を表すtime_in_queue と、デバイスがIOリクエストを発行していた時間を表す io_ticks を更新しています。io_ticksには前回のリクエスト完了から、今回のリクエスト完了までを加算し、time_in_queueにはそれに実行中のリクエスト数を掛けたものを加算しているのがわかります。

tatic void part_round_stats_single(int cpu, struct hd_struct *part,
                    unsigned long now) 
{
    if (now == part->stamp)
        return;

    if (part_in_flight(part)) {
        __part_stat_add(cpu, part, time_in_queue,
                part_in_flight(part) * (now - part->stamp));
        __part_stat_add(cpu, part, io_ticks, (now - part->stamp));
    }    
    part->stamp = now; 
}
Etsukata blog: iostat -x の出力を Linux Kernel ソースコードから理解する

プロセスアカウンティングのように定期的に割込み(tick)を入れて加算していくのではなく、I/Oのたびにデバイスごとに存在する構造体(hd_struct)に加算していっているというイメージで合っていそう(想定通り)。「io_ticksには前回のリクエスト完了から、今回のリクエスト完了までを加算」すると、サービスタイム(io_ticks)にデバイスでI/O処理中の時間以外も加算されてしまいそうな気がするが、ちょっと調べてみた限りではよくわからなかったので、今後の課題にしよう。この記事、よく見ると1年前に書かれたもの。なんでもっと早く見つけられなかったんだろう。。。

%utilではなくサービスタイム(svctm)の話しになっていますが、

%util = svctm(インターバル期間中のsvctmの合計) / インターバル(iostat -x 5 とした場合、インターバルは5秒)

なので、サービスタイムがわかれば、%util がわかるわけです。

SystemTap で block/blk-core.c#part_round_stats_single にバックトレースを仕掛けてみた(さくらのVPSでやりました)。

#!/usr/bin/stap -v
probe kernel.function("part_round_stats_single"){
        printf("%s[%d]\n",execname(),pid())
        print_backtrace()
}

こんな感じ。

# uname -r
2.6.32-358.18.1.el6.x86_64
# ./part_round_stats_single.stp
Pass 1: parsed user script and 86 library script(s) using 195560virt/24276res/3064shr/21488data kb, in 140usr/20sys/159real ms.
Pass 2: analyzed script: 2 probe(s), 3 function(s), 2 embed(s), 0 global(s) using 350432virt/49524res/4128shr/45660data kb, in 520usr/170sys/687real ms.
Pass 3: using cached /root/.systemtap/cache/24/stap_24b4e258281281b492ad5030573ce095_2415.c
Pass 4: using cached /root/.systemtap/cache/24/stap_24b4e258281281b492ad5030573ce095_2415.ko
Pass 5: starting run.
WARNING: Missing unwind data for module, rerun with 'stap -d jbd2'
WARNING: Missing unwind data for module, rerun with 'stap -d virtio_blk'
jbd2/vda3-8[363]
 0xffffffff81256eec : part_round_stats+0x2c/0x110 [kernel]
 0xffffffff8125acee : drive_stat_acct+0xee/0x130 [kernel]
 0xffffffff8125ea50 : blk_queue_bio+0x110/0x5d0 [kernel]
 0xffffffff8125d09e : generic_make_request+0x24e/0x500 [kernel]
 0xffffffff8125d3dd : submit_bio+0x8d/0x120 [kernel]
 0xffffffff811b4f56 : submit_bh+0xf6/0x150 [kernel]
 0xffffffffa007ec08 [jbd2]
 0xffffffff810096f0 : __switch_to+0xd0/0x320 [kernel] (inexact)
 0xffffffff81081b5b : try_to_del_timer_sync+0x7b/0xe0 [kernel] (inexact)
 0xffffffffa0085148 [jbd2] (inexact)
 0xffffffff81096da0 : autoremove_wake_function+0x0/0x40 [kernel] (inexact)
 0xffffffffa0085090 [jbd2] (inexact)
 0xffffffff81096a36 : kthread+0x96/0xa0 [kernel] (inexact)
 0xffffffff8100c0ca : child_rip+0xa/0x20 [kernel] (inexact)
 0xffffffff810969a0 : kthread+0x0/0xa0 [kernel] (inexact)
 0xffffffff8100c0c0 : child_rip+0x0/0x20 [kernel] (inexact)
(中略)
swapper[0]
 0xffffffff81256eec : part_round_stats+0x2c/0x110 [kernel]
 0xffffffff8125dd4a : blk_finish_request+0x18a/0x260 [kernel]
 0xffffffff8125de6b : __blk_end_request_all+0x4b/0x60 [kernel]
 0xffffffffa005822a [virtio_blk]
swapper[0]
 0xffffffff81256f58 : part_round_stats+0x98/0x110 [kernel]
 0xffffffff8125dd4a : blk_finish_request+0x18a/0x260 [kernel]
 0xffffffff8125de6b : __blk_end_request_all+0x4b/0x60 [kernel]
 0xffffffffa005822a [virtio_blk]
swapper[0]
 0xffffffff81256eec : part_round_stats+0x2c/0x110 [kernel]
 0xffffffff8125dd4a : blk_finish_request+0x18a/0x260 [kernel]
 0xffffffff8125de6b : __blk_end_request_all+0x4b/0x60 [kernel]
 0xffffffffa005822a [virtio_blk]
swapper[0]
 0xffffffff81256f58 : part_round_stats+0x98/0x110 [kernel]
 0xffffffff8125dd4a : blk_finish_request+0x18a/0x260 [kernel]
 0xffffffff8125de6b : __blk_end_request_all+0x4b/0x60 [kernel]
 0xffffffffa005822a [virtio_blk]

参考

詳解 Linuxカーネル 第3版

詳解 Linuxカーネル 第3版

図 14-3

Systems Performance: Enterprise and the Cloud

Systems Performance: Enterprise and the Cloud

P.436

The most important metric for delivered performance is await. If the application and file system use a technique to mitigate write latency (e.g., write-through), w_await may not matter as much, and you can focus on r_await instead.
For resource usage and capacity planning, %util is important, but bear in mind it is only a measure of busyness (non-idle time) and may mean little for virtual devices backed by multiple disks. Those devices may be better understood by the load applied: IOPS (r/s + w/s) and throughput (rkB/s + wkB/s).
The r_await and w_await columns are newer additions to the iostat(1) tool; previous versions had just await. The iostat(1) man page warns that the svctm field will be removed in future versions as the metric is considered to be inaccurate. (I don’t think it is inaccurate, but I do think it may have misled people, since it is an inferred value and not a measurement of device latency.)


追記(2014/10/17):
@ さんのブログエントリが以下の通り修正されていました。ありがとうございます!これで謎も解けた。

io_ticksには前回のリクエスト完了から、今回のリクエスト完了までを加算し、訂正(@yohei-aさんのエントリ:「iostat はどのように %util を算出しているか(3)」を読んで間違いに気づきました。ありがとうございます!) io_ticksにはIO 発行中の時間(part_in_flightが0より大きい時間)を加算し、time_in_queueにはそれに実行中のリクエスト数を掛けたものを加算しているのがわかります。

Etsukata blog: iostat -x の出力を Linux Kernel ソースコードから理解する