FM / lwtools

/usr/share/systemtap/examples/lwtools

Name	Size	Mode	Actions
accept2close-nd.8	1424	0644	edit dl rm
accept2close-nd.meta	597	0644	edit dl rm
accept2close-nd.stp	1798	0755	edit dl rm
accept2close-nd.txt	3385	0644	edit dl rm
biolatency-nd.8	1671	0644	edit dl rm
biolatency-nd.meta	622	0644	edit dl rm
biolatency-nd.stp	2071	0755	edit dl rm
biolatency-nd_example.txt	7362	0644	edit dl rm
bitesize-nd.8	1157	0644	edit dl rm
bitesize-nd.meta	491	0644	edit dl rm
bitesize-nd.stp	1543	0755	edit dl rm
bitesize-nd_example.txt	3426	0644	edit dl rm
execsnoop-nd.8	1235	0644	edit dl rm
execsnoop-nd.meta	570	0644	edit dl rm
execsnoop-nd.stp	1283	0755	edit dl rm
execsnoop-nd_example.txt	2585	0644	edit dl rm
fslatency-nd.8	1930	0644	edit dl rm
fslatency-nd.meta	660	0644	edit dl rm
fslatency-nd.stp	3982	0755	edit dl rm
fslatency-nd_example.txt	13384	0644	edit dl rm
fsslower-nd.8	1753	0644	edit dl rm
fsslower-nd.meta	623	0644	edit dl rm
fsslower-nd.stp	3715	0755	edit dl rm
fsslower-nd_example.txt	1938	0644	edit dl rm
killsnoop-nd.8	1131	0644	edit dl rm
killsnoop-nd.meta	384	0644	edit dl rm
killsnoop-nd.stp	1281	0755	edit dl rm
killsnoop-nd_example.txt	1908	0644	edit dl rm
opensnoop-nd.8	1268	0644	edit dl rm
opensnoop-nd.meta	357	0644	edit dl rm
opensnoop-nd.stp	1026	0755	edit dl rm
opensnoop-nd_example.txt	1124	0644	edit dl rm
README	107	0644	edit dl rm
rwtime-nd.8	1146	0644	edit dl rm
rwtime-nd.meta	412	0644	edit dl rm
rwtime-nd.stp	1599	0755	edit dl rm
rwtime-nd_example.txt	4185	0644	edit dl rm
syscallbypid-nd.8	1089	0644	edit dl rm
syscallbypid-nd.meta	404	0644	edit dl rm
syscallbypid-nd.stp	1100	0755	edit dl rm
syscallbypid-nd_example.txt	9322	0644	edit dl rm

Edit: /usr/share/systemtap/examples/lwtools/biolatency-nd_example.txt (7362B)

Examples of biolatency-nd.stp, the Linux SystemTap version.

Measuring block I/O (storage I/O, ie, disk I/O) latency until Ctrl-C:

# ./biolatency-nd.stp 
Tracing block I/O... Hit Ctrl-C to end.
^C
bio latency (ns):
   value |-------------------------------------------------- count
  131072 |                                                    0
  262144 |                                                    0
  524288 |@@                                                  5
 1048576 |@@                                                  4
 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@                           49
 4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                        55
 8388608 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          82
16777216 |@@@@@@@@@@@@@@@@@@                                 37
33554432 |                                                    0
67108864 |                                                    0

This shows a distribution between aout 1 and 16 milliseconds, which is expected
for current rotational disk I/O.

A more interesting distribution:

# ./biolatency-nd.stp 
Tracing block I/O... Hit Ctrl-C to end.
^C
bio latency (ns):
     value |-------------------------------------------------- count
     32768 |                                                      0
     65536 |                                                      0
    131072 |                                                     10
    262144 |@@@@@@@@@                                           450
    524288 |@@@                                                 159
   1048576 |                                                     26
   2097152 |                                                     35
   4194304 |                                                     18
   8388608 |@@                                                  112
  16777216 |@@@@                                                195
  33554432 |@@@@@@@@@                                           452
  67108864 |@@@@@@@@@@@@@@@@@@@@@@                             1065
 134217728 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  2398
 268435456 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@          2008
 536870912 |                                                      0
1073741824 |                                                      0

This shows a bimodal distribution with a low-latency mode around 0.26
milliseconds, which may be on-disk cache hits, and then a high-latency mode
between around 16 and 268 milliseconds. Such high latency is likely
caused by queueing, which can be investigated further using custom
SystemTap invocations as well as the "avgqu-sz" column from iostat(1).

biolatency-nd.stp accepts an optional interval and count as arguments. Measuring
block I/O latency, and printing a report every second, five times:

# ./biolatency-nd.stp 1 5
Tracing block I/O... Output every 1 secs.

bio latency (ns):
   value |-------------------------------------------------- count
   32768 |                                                     0
   65536 |                                                     0
  131072 |@@                                                  28
  262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   486
  524288 |@@@@@@@@@@@@@@@@@@@                                198
 1048576 |@@@@@@@@@                                           98
 2097152 |@@@@@@                                              61
 4194304 |@@@                                                 35
 8388608 |@                                                   17
16777216 |                                                     3
33554432 |                                                     0
67108864 |                                                     0

bio latency (ns):
   value |-------------------------------------------------- count
   32768 |                                                     0
   65536 |                                                     0
  131072 |@@                                                  22
  262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@      505
  524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                  370
 1048576 |@@@@@@@@                                            91
 2097152 |@@                                                  31
 4194304 |@                                                   20
 8388608 |@                                                   20
16777216 |                                                     4
33554432 |                                                     0
67108864 |                                                     0

bio latency (ns):
   value |-------------------------------------------------- count
   32768 |                                                     0
   65536 |                                                     0
  131072 |@@@@                                                70
  262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   826
  524288 |@@@@@@@@@@@@@@@@@@@                                333
 1048576 |@@@                                                 52
 2097152 |                                                    11
 4194304 |                                                     7
 8388608 |@                                                   17
16777216 |                                                     5
33554432 |                                                     0
67108864 |                                                     0

bio latency (ns):
    value |-------------------------------------------------- count
    32768 |                                                     0
    65536 |                                                     0
   131072 |@@                                                  35
   262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     559
   524288 |@@@@@@@@@@@@@@@@@@@@@@                             270
  1048576 |@@@@@@                                              82
  2097152 |@@                                                  34
  4194304 |@                                                   17
  8388608 |@                                                   19
 16777216 |                                                     9
 33554432 |                                                     2
 67108864 |                                                     0
134217728 |                                                     0

bio latency (ns):
   value |-------------------------------------------------- count
   32768 |                                                     0
   65536 |                                                     0
  131072 |@@@                                                 57
  262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   877
  524288 |@@@@@@@@@@@@@@@                                    270
 1048576 |@@@@                                                85
 2097152 |@@                                                  46
 4194304 |                                                     7
 8388608 |                                                    15
16777216 |                                                    10
33554432 |                                                     0
67108864 |                                                     0

These disk I/O were much faster, with a mode around 0.25 ms.

cmd: