iostat は IO の出力速度や待ち時間の計測によく使われるコマンドです。"-x" オプションをつけると、平均待ち時間(await)やリクエストキュー長(avgqu-sz)、サービスタイム(svctm)などの詳細な情報を出力することができ、とても便利です。データベースをはじめとし、各種アプリケーションのパフォーマンスを計測するための重要な指標となります。
今回は、これらの出力結果について、より詳細かつ正確な意味を、Linux Kernelのソースコードを読んで理解しましょう。かなり長くなってしまったので、意味を把握したい方は下の方の "iostat -x 出力結果まとめ" をご覧ください。
iostatの挙動
まず、iostatの挙動を調べます。iostatは、read_sysfs_file_stat()で指定したインターバルごとに /proc/diskstats の情報を読み取り、compute_ext_disk_stats()で各種統計情報の計算を行い、結果をwrite_ext_stat()で出力します。read_sysfs_file_stat()、compute_ext_disk_stats()、write_ext_stat()の一部を下記に示します。
read_sysfs_file_stat():
int read_sysfs_file_stat(int curr, char *filename, char *dev_name)
{
...
i = fscanf(fp, "%lu %lu %lu %lu %lu %lu %lu %u %u %u %u",
&rd_ios, &rd_merges_or_rd_sec, &rd_sec_or_wr_ios, &rd_ticks_or_wr_sec,
&wr_ios, &wr_merges, &wr_sec, &wr_ticks, &ios_pgr, &tot_ticks, &rq_ticks);
if (i == 11) {
/* Device or partition */
sdev.rd_ios = rd_ios;
sdev.rd_merges = rd_merges_or_rd_sec;
sdev.rd_sectors = rd_sec_or_wr_ios;
sdev.rd_ticks = (unsigned int) rd_ticks_or_wr_sec;
sdev.wr_ios = wr_ios;
sdev.wr_merges = wr_merges;
sdev.wr_sectors = wr_sec;
sdev.wr_ticks = wr_ticks;
sdev.ios_pgr = ios_pgr;
sdev.tot_ticks = tot_ticks;
sdev.rq_ticks = rq_ticks;
}
...
}
read_sysfs_file_stat() では、/proc/diskstatsの各種フィールドを記録しています。これらパラメータが、カーネル内でどのような意味を持つかを詳細に理解するのが本資料の目的です。
compute_ext_disk_stat():
/*
***************************************************************************
* Compute "extended" device statistics (service time, etc.).
*
* IN:
* @sdc Structure with current device statistics.
* @sdp Structure with previous device statistics.
* @itv Interval of time in jiffies.
*
* OUT:
* @xds Structure with extended statistics.
***************************************************************************
*/
void compute_ext_disk_stats(struct stats_disk *sdc, struct stats_disk *sdp,
unsigned long long itv, struct ext_disk_stats *xds)
{
double tput
= ((double) (sdc->nr_ios - sdp->nr_ios)) * HZ / itv;
xds->util = S_VALUE(sdp->tot_ticks, sdc->tot_ticks, itv);
xds->svctm = tput ? xds->util / tput : 0.0;
/*
* Kernel gives ticks already in milliseconds for all platforms
* => no need for further scaling.
*/
xds->await = (sdc->nr_ios - sdp->nr_ios) ?
((sdc->rd_ticks - sdp->rd_ticks) + (sdc->wr_ticks - sdp->wr_ticks)) /
((double) (sdc->nr_ios - sdp->nr_ios)) : 0.0;
xds->arqsz = (sdc->nr_ios - sdp->nr_ios) ?
((sdc->rd_sect - sdp->rd_sect) + (sdc->wr_sect - sdp->wr_sect)) /
((double) (sdc->nr_ios - sdp->nr_ios)) : 0.0;
}
util, svctm, await, avgrq-sz パラメータについて、各種計算を行っています。
write_ext_stat():
/*
***************************************************************************
* Display extended stats, read from /proc/{diskstats,partitions} or /sys.
*
* IN:
* @curr Index in array for current sample statistics.
* @itv Interval of time.
* @fctr Conversion factor.
* @shi Structures describing the devices and partitions.
* @ioi Current sample statistics.
* @ioj Previous sample statistics.
***************************************************************************
*/
void write_ext_stat(int curr, unsigned long long itv, int fctr,
struct io_hdr_stats *shi, struct io_stats *ioi,
struct io_stats *ioj)
{
...
/* rrq/s wrq/s r/s w/s rsec wsec rqsz qusz await r_await w_await svctm %util */
printf(" %8.2f %8.2f %7.2f %7.2f %8.2f %8.2f %8.2f %8.2f %7.2f %7.2f %7.2f %6.2f %6.2f\n",
S_VALUE(ioj->rd_merges, ioi->rd_merges, itv),
S_VALUE(ioj->wr_merges, ioi->wr_merges, itv),
S_VALUE(ioj->rd_ios, ioi->rd_ios, itv),
S_VALUE(ioj->wr_ios, ioi->wr_ios, itv),
ll_s_value(ioj->rd_sectors, ioi->rd_sectors, itv) / fctr,
ll_s_value(ioj->wr_sectors, ioi->wr_sectors, itv) / fctr,
xds.arqsz,
S_VALUE(ioj->rq_ticks, ioi->rq_ticks, itv) / 1000.0,
xds.await,
r_await,
w_await,
/* The ticks output is biased to output 1000 ticks per second */
xds.svctm,
/*
* Again: Ticks in milliseconds.
* In the case of a device group (option -g), shi->used is the number of
* devices in the group. Else shi->used equals 1.
*/
shi->used ? xds.util / 10.0 / (double) shi->used
: xds.util / 10.0); /* shi->used should never be null here */
...
}
compute_ext_disk_stat() で計算した結果と併せて、各種情報を出力しています。S_VALUEは差分をとってインターバルで割るマクロです。
/proc/diskstats 詳細
さて、iostat コマンドの挙動は把握できました。ポイントとなるのは、"/proc/diskstats では どのような情報を出力しているのか" です。これらを正確に理解するには、カーネルのソースコードを読む必要がでてきます。
まず、ソースコードを読む前にドキュメントを調べましょう。カーネルソースディレクトリ以下に/Documentation/iostats.txtがあります。以下に一部を抜粋します。
Documentaition/iostast.txt:
Field 1 -- # of reads completed
This is the total number of reads completed successfully.
Field 2 -- # of reads merged, field 6 -- # of writes merged
Reads and writes which are adjacent to each other may be merged for
efficiency. Thus two 4K reads may become one 8K read before it is
ultimately handed to the disk, and so it will be counted (and queued)
as only one I/O. This field lets you know how often this was done.
Field 3 -- # of sectors read
This is the total number of sectors read successfully.
Field 4 -- # of milliseconds spent reading
This is the total number of milliseconds spent by all reads (as
measured from __make_request() to end_that_request_last()).
Field 5 -- # of writes completed
This is the total number of writes completed successfully.
Field 6 -- # of writes merged
See the description of field 2.
Field 7 -- # of sectors written
This is the total number of sectors written successfully.
Field 8 -- # of milliseconds spent writing
This is the total number of milliseconds spent by all writes (as
measured from __make_request() to end_that_request_last()).
Field 9 -- # of I/Os currently in progress
The only field that should go to zero. Incremented as requests are
given to appropriate struct request_queue and decremented as they finish.
Field 10 -- # of milliseconds spent doing I/Os
This field increases so long as field 9 is nonzero.
Field 11 -- weighted # of milliseconds spent doing I/Os
This field is incremented at each I/O start, I/O completion, I/O
merge, or read of these stats by the number of I/Os in progress
(field 9) times the number of milliseconds spent doing I/O since the
last update of this field. This can provide an easy measure of both
I/O completion time and the backlog that may be accumulating.
iostat.txtに加え、Documentation/block/stat.txtにも有用な情報があります。
Name units description ---- ----- ----------- read I/Os requests number of read I/Os processed read merges requests number of read I/Os merged with in-queue I/O read sectors sectors number of sectors read read ticks milliseconds total wait time for read requests write I/Os requests number of write I/Os processed write merges requests number of write I/Os merged with in-queue I/O write sectors sectors number of sectors written write ticks milliseconds total wait time for write requests in_flight requests number of I/Os currently in flight io_ticks milliseconds total time this block device has been active time_in_queue milliseconds total wait time for all requestsDocumentationを読むとフィールドの意味が大まかに理解できます。
ではソースコードを読んでいきます。/proc/diskstats を read した時に呼ばれるのは diskstats_show() です。
diskstats_show():
tatic int diskstats_show(struct seq_file *seqf, void *v)
{
struct gendisk *gp = v;
struct disk_part_iter piter;
struct hd_struct *hd;
char buf[BDEVNAME_SIZE];
int cpu;
...
while ((hd = disk_part_iter_next(&piter))) {
cpu = part_stat_lock();
part_round_stats(cpu, hd);
part_stat_unlock();
seq_printf(seqf, "%4d %7d %s %lu %lu %lu "
"%u %lu %lu %lu %u %u %u %u\n",
MAJOR(part_devt(hd)), MINOR(part_devt(hd)),
disk_name(gp, hd->partno, buf),
part_stat_read(hd, ios[READ]),
part_stat_read(hd, merges[READ]),
part_stat_read(hd, sectors[READ]),
jiffies_to_msecs(part_stat_read(hd, ticks[READ])),
part_stat_read(hd, ios[WRITE]),
part_stat_read(hd, merges[WRITE]),
part_stat_read(hd, sectors[WRITE]),
jiffies_to_msecs(part_stat_read(hd, ticks[WRITE])),
part_in_flight(hd),
jiffies_to_msecs(part_stat_read(hd, io_ticks)),
jiffies_to_msecs(part_stat_read(hd, time_in_queue))
);
}
...
}
part_stat_readマクロで hd_struct から各種情報を読み取っていることがわかります。キーとなる構造体は disk_stats です。下記には、// 以下に対応する iostat -x のフィールドを追記してあります。
disk_stats:
struct disk_stats {
unsigned long sectors[2]; /* READs and WRITEs */ // rsec/s wsec/s avgrq-sz
unsigned long ios[2]; // r/s w/s
unsigned long merges[2]; // rrqm/s wrqm/s
unsigned long ticks[2]; // await r_wait w_wait
unsigned long io_ticks; // %util svctm
unsigned long time_in_queue; // avgqu-sz
};
disk_statsのメンバが更新されるタイミングを追っていきましょう。
hd_struct の各メンバが更新されるのは、blk_account_io_completion() および、 blk_account_io_done() 、drive_stat_acct() です。blk_account_io_completion() と blk_account_io_done() は、リクエスト完了時に呼ばれるblk_end_bidi_request() から呼ばれます。
コールグラフはざっと以下のような感じです。
blk_end_bidi_request()
-> blk_update_bidi_request()
-> blk_update_request()
-> blk_account_io_completion()
-> blk_finish_request()
-> blk_account_io_done()
blk_account_io_completion():
static void blk_account_io_completion(struct request *req, unsigned int bytes)
{
if (blk_do_io_stat(req)) {
const int rw = rq_data_dir(req);
struct hd_struct *part;
int cpu;
cpu = part_stat_lock();
part = req->part;
part_stat_add(cpu, part, sectors[rw], bytes >> 9);
part_stat_unlock();
}
}
blk_account_io_completion() では、IOが完了したバイト数をsectors に加算しています。blk_account_io_done():
static void blk_account_io_done(struct request *req)
{
/*
* Account IO completion. flush_rq isn't accounted as a
* normal IO on queueing nor completion. Accounting the
* containing request is enough.
*/
if (blk_do_io_stat(req) && !(req->cmd_flags & REQ_FLUSH_SEQ)) {
unsigned long duration = jiffies - req->start_time;
const int rw = rq_data_dir(req);
struct hd_struct *part;
int cpu;
cpu = part_stat_lock();
part = req->part;
part_stat_inc(cpu, part, ios[rw]);
part_stat_add(cpu, part, ticks[rw], duration);
part_round_stats(cpu, part);
part_dec_in_flight(part, rw);
hd_struct_put(part);
part_stat_unlock();
}
}
blk_account_io_done() では、IO回数を表す ios をインクリメントし、 await の計算に使われる ticks に duration を加算しています。さらに実行中のリクエスト数(＝リクエストキューの長さ)を part_dec_in_flight()でデクリメントしています。
durationについては、後ほど詳述します。
part_round_stats() では、その延長で、全てのリクエストがキューにいた時間の積算値を表すtime_in_queue と、デバイスがIOリクエストを発行して、未完了のIOが存在する時間を表す io_ticks を更新しています。
static 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;
}
blk_account_io_done() で ticks に duration を加えています。duration は submit_bio の延長で呼ばれる blk_rq_init()でカウントが開始されます。
コールスタックは以下のような感じ。
submit_bio()
-> generic_make_request()
-> blk_queue_bio()
-> get_request()
-> blk_rq_init()
blk_rq_init():
void blk_rq_init(struct request_queue *q, struct request *rq)
{
...
rq->start_time = jiffies;
...
}
最後に、hd_struct の merges を更新する drive_stat_acct() についてです。これは、リクエストをつくる際に、bioをリクエストにマージしようと試みる関数
bio_attempt_back_merge() または、リクエストを作成する blk_queue_bio() で呼ばれます。マージできたら merges カウントをインクリメントし、できなかったら実行中のリクエスト数をインクリメントし、io_ticksカウント用のstampを初期化(part_round_stat())します。
コールスタックは以下のような感じ。
submit_bio()
-> generic_make_request()
-> blk_queue_bio()
-> bio_attempt_back_merge()
-> drive_stat_acct()
または
submit_bio()
-> generic_make_request()
-> blk_queue_bio()
-> drive_stat_acct()
drive_stat_acct():
static void drive_stat_acct(struct request *rq, int new_io)
{
struct hd_struct *part;
...
if (!new_io) {
part = rq->part;
part_stat_inc(cpu, part, merges[rw]);
} else {
...
part_round_stats(cpu, part);
part_inc_in_flight(part, rw);
...
}
以上でiostat -x の出力を読み解くカーネル内の情報は手にはいりました。
iostat -x 出力結果まとめ
カーネルのソースコードを読んで得た情報から、 iostat -x の出力フィールドそれぞれについて、詳細な意味をまとめます。
rrqm/s wrqm/s :
一秒間にマージされたリード/ライト・リクエストの数。リクエストを作るgeneric_make_request()の延長で、bioをリクエストにマージしようと試み(bio_attempt_back_merge())、成功したらカウントされる。
r/s w/s:
一秒間に発行したリード/ライト・リクエストの数。リクエストが完了した際に呼ばれるblk_end_bidi_request()の延長でカウント(blk_account_io_done())している。
rkB/s wkB/s:
一秒間に発行したリード/ライト・リクエストが読み書きに成功したkB数。リクエストが完了した際に呼ばれるblk_end_bidi_request()の延長でカウント(blk_account_io_completion()) している。
avgrq-sz:
発行が完了したリクエストの平均サイズ。
avgqu-sz:
平均リクエストキューの長さの指標となる数値。正確にリクエストキューの長さというわけではなく、IOリクエストが作成されてから、発行が完了されるまでの総待ち時間値(time_in_queue)の平均。
await:
リード・ライトリクエストが作成(get_request())されてから、リクエスト完了(blk_finish_request())までにかかる時間の平均値。
r_await w_await:
それぞれ、awaitのリード版・ライト版。
svctm:
一回のIO発行にかかる時間(リクエストがキューに積まれている時間を含まない)の平均値。awaitとは異なり、IOスケジューラでリクエストがqueueに積まれている時間は含まれない。この数値によりデバイスがIOを発行してから完了にかかるまでの時間がわかる。
%util:
IO発行にかかる時間(リクエストがキューに積まれている時間を含まない)の、インターバルに占める割合(%)
以上、長くなりましたが、(若干端折りつつ)iostat -x の出力を Kernel ソースコードから追ってみました。ソースコードを追うと、それぞれの出力結果の意味をより正確につかむことができます。また、avgqu-szが正確にリクエストキューの長さの平均を表すものではなく、その指標になる数値(総待ち時間の平均)であることなど、発見がありました。
参考情報
Documentation/block/stat.txt
Documentation/iostats.txt
GitHub: sysstat/sysstat
