5.2.7. Periodically Print I/O Block Time

This section describes how to track the amount of time each block I/O requests spends waiting for completion. This is useful in determining whether there are too many outstanding block I/O operations at any given time.

ioblktime.stp

#! /usr/bin/env stapglobal req_time, etimesprobe ioblock.request{ req_time[$bio] = gettimeofday_us()}probe ioblock.end{ t = gettimeofday_us() s = req_time[$bio] delete req_time[$bio] if (s) { etimes[devname, bio_rw_str(rw)] <<< t - s }}probe timer.s(10), end { ansi_clear_screen() printf("%10s %3s %10s %10s %10s\n", "device", "rw", "total (us)", "count", "avg (us)") foreach ([dev,rw] in etimes - limit 20) { printf("%10s %3s %10d %10d %10d\n", dev, rw, @sum(etimes[dev,rw]), @count(etimes[dev,rw]), @avg(etimes[dev,rw])) } delete etimes}

ioblktime.stp computes the average waiting time for block I/O per device, and prints a list every 10 seconds. As always, you can revise this refresh rate by editing the specified value in probe timer.s(10), end {.

In some cases, there can be too many outstanding block I/O operations, at which point the script can exceed the default number of MAXMAPENTRIES. MAXMAPENTRIES is the maximum number of rows in an array if the array size is not specified explicitly when declared. If the script exceeds the default MAXMAPENTRIES value of 2048, run the script again with the stap option -DMAXMAPENTRIES=10000.

Example 5.12. ioblktime.stp Sample Output

 device rw total (us) count avg (us) sda W 9659 6 1609 dm-0 W 20278 6 3379 dm-0 R 20524 5 4104 sda R 19277 5 3855

Example 5.12, “ioblktime.stp Sample Output” displays the device name, operations performed (rw), total wait time of all operations (total(us)), number of operations (count), and average wait time for all those operations (avg (us)). The times tallied by the script are in microseconds.