Server : Apache System : Linux server2.corals.io 4.18.0-348.2.1.el8_5.x86_64 #1 SMP Mon Nov 15 09:17:08 EST 2021 x86_64 User : corals ( 1002) PHP Version : 7.4.33 Disable Function : exec,passthru,shell_exec,system Directory : /opt/rh/gcc-toolset-11/root/usr/share/systemtap/examples/lwtools/ |
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.