-
Notifications
You must be signed in to change notification settings - Fork 38
/
Copy pathbiolatency-nd_example.txt
143 lines (122 loc) · 7.19 KB
/
biolatency-nd_example.txt
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
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.