Skip to content

Commit 44e6877

Browse files
brendangreggbrendangregg
committed
biolatency -D
1 parent 50bbca4 commit 44e6877

3 files changed

Lines changed: 98 additions & 7 deletions

File tree

‎man/man8/biolatency.8‎

Lines changed: 8 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@
22
.SH NAME
33
biolatency \- Summarize block device I/O latency as a histogram.
44
.SH SYNOPSIS
5-
.B biolatency [\-h] [\-T] [\-Q] [\-m] [interval [count]]
5+
.B biolatency [\-h] [\-T] [\-Q] [\-m] [\-D] [interval [count]]
66
.SH DESCRIPTION
77
biolatency traces block device I/O (disk I/O), and records the distribution
88
of I/O latency (time). This is printed as a histogram either on Ctrl-C, or
@@ -30,6 +30,9 @@ Include timestamps on output.
3030
\-m
3131
Output histogram in milliseconds.
3232
.TP
33+
\-D
34+
Print a histogram per disk device.
35+
.TP
3336
interval
3437
Output interval, in seconds.
3538
.TP
@@ -53,6 +56,10 @@ include timestamps on output:
5356
Include OS queued time in I/O time:
5457
#
5558
.B biolatency \-Q
59+
.TP
60+
Show a latency histogram for each disk device separately:
61+
#
62+
.B biolatency \-D
5663
.SH FIELDS
5764
.TP
5865
usecs

‎tools/biolatency‎

Lines changed: 25 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -3,7 +3,7 @@
33
# biolatency Summarize block device I/O latency as a histogram.
44
# For Linux, uses BCC, eBPF.
55
#
6-
# USAGE: biolatency [-h] [-T] [-Q] [-m] [interval] [count]
6+
# USAGE: biolatency [-h] [-T] [-Q] [-m] [-D] [interval] [count]
77
#
88
# Copyright (c) 2015 Brendan Gregg.
99
# Licensed under the Apache License, Version 2.0 (the "License")
@@ -21,6 +21,7 @@ examples = """examples:
2121
./biolatency 1 10 # print 1 second summaries, 10 times
2222
./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
2323
./biolatency -Q # include OS queued time in I/O time
24+
./biolatency -D # show each disk device separately
2425
"""
2526
parser = argparse.ArgumentParser(
2627
description="Summarize block device I/O latency as a histogram",
@@ -32,6 +33,8 @@ parser.add_argument("-Q", "--queued", action="store_true",
3233
help="include OS queued time in I/O time")
3334
parser.add_argument("-m", "--milliseconds", action="store_true",
3435
help="millisecond histogram")
36+
parser.add_argument("-D", "--disks", action="store_true",
37+
help="print a histogram per disk device")
3538
parser.add_argument("interval", nargs="?", default=99999999,
3639
help="output interval, in seconds")
3740
parser.add_argument("count", nargs="?", default=99999999,
@@ -40,13 +43,17 @@ args = parser.parse_args()
4043
countdown = int(args.count)
4144
debug = 0
4245

43-
# load BPF program
46+
# define BPF program
4447
bpf_text = """
4548
#include <uapi/linux/ptrace.h>
4649
#include <linux/blkdev.h>
4750
48-
BPF_HISTOGRAM(dist);
51+
typedef struct disk_key {
52+
char disk[DISK_NAME_LEN];
53+
u64 slot;
54+
} disk_key_t;
4955
BPF_HASH(start, struct request *);
56+
STORAGE
5057
5158
// time block I/O
5259
int trace_req_start(struct pt_regs *ctx, struct request *req)
@@ -70,18 +77,31 @@ int trace_req_completion(struct pt_regs *ctx, struct request *req)
7077
FACTOR
7178
7279
// store as histogram
73-
dist.increment(bpf_log2l(delta));
80+
STORE
7481
7582
start.delete(&req);
7683
return 0;
7784
}
7885
"""
86+
87+
# code substitutions
7988
if args.milliseconds:
8089
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
8190
label = "msecs"
8291
else:
8392
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
8493
label = "usecs"
94+
if args.disks:
95+
bpf_text = bpf_text.replace('STORAGE',
96+
'BPF_HISTOGRAM(dist, disk_key_t);')
97+
bpf_text = bpf_text.replace('STORE',
98+
'disk_key_t key = {.slot = bpf_log2l(delta)}; ' +
99+
'bpf_probe_read(&key.disk, sizeof(key.disk), ' +
100+
'req->rq_disk->disk_name); dist.increment(key);')
101+
else:
102+
bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);')
103+
bpf_text = bpf_text.replace('STORE',
104+
'dist.increment(bpf_log2l(delta));')
85105
if debug:
86106
print(bpf_text)
87107

@@ -110,7 +130,7 @@ while (1):
110130
if args.timestamp:
111131
print("%-8s\n" % strftime("%H:%M:%S"), end="")
112132

113-
dist.print_log2_hist(label)
133+
dist.print_log2_hist(label, "disk")
114134
dist.clear()
115135

116136
countdown -= 1

‎tools/biolatency_example.txt‎

Lines changed: 65 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -136,10 +136,72 @@ queues of their own, which are always included in the latency, with or
136136
without -Q.
137137

138138

139+
The -D option will print a histogram per disk. Eg:
140+
141+
# ./biolatency -D
142+
Tracing block device I/O... Hit Ctrl-C to end.
143+
^C
144+
145+
Bucket disk = 'xvdb'
146+
usecs : count distribution
147+
0 -> 1 : 0 | |
148+
2 -> 3 : 0 | |
149+
4 -> 7 : 0 | |
150+
8 -> 15 : 0 | |
151+
16 -> 31 : 0 | |
152+
32 -> 63 : 0 | |
153+
64 -> 127 : 0 | |
154+
128 -> 255 : 1 | |
155+
256 -> 511 : 33 |********************** |
156+
512 -> 1023 : 36 |************************ |
157+
1024 -> 2047 : 58 |****************************************|
158+
2048 -> 4095 : 51 |*********************************** |
159+
4096 -> 8191 : 21 |************** |
160+
8192 -> 16383 : 2 |* |
161+
162+
Bucket disk = 'xvdc'
163+
usecs : count distribution
164+
0 -> 1 : 0 | |
165+
2 -> 3 : 0 | |
166+
4 -> 7 : 0 | |
167+
8 -> 15 : 0 | |
168+
16 -> 31 : 0 | |
169+
32 -> 63 : 0 | |
170+
64 -> 127 : 0 | |
171+
128 -> 255 : 1 | |
172+
256 -> 511 : 38 |*********************** |
173+
512 -> 1023 : 42 |************************* |
174+
1024 -> 2047 : 66 |****************************************|
175+
2048 -> 4095 : 40 |************************ |
176+
4096 -> 8191 : 14 |******** |
177+
178+
Bucket disk = 'xvda1'
179+
usecs : count distribution
180+
0 -> 1 : 0 | |
181+
2 -> 3 : 0 | |
182+
4 -> 7 : 0 | |
183+
8 -> 15 : 0 | |
184+
16 -> 31 : 0 | |
185+
32 -> 63 : 0 | |
186+
64 -> 127 : 0 | |
187+
128 -> 255 : 0 | |
188+
256 -> 511 : 18 |********** |
189+
512 -> 1023 : 67 |************************************* |
190+
1024 -> 2047 : 35 |******************* |
191+
2048 -> 4095 : 71 |****************************************|
192+
4096 -> 8191 : 65 |************************************ |
193+
8192 -> 16383 : 65 |************************************ |
194+
16384 -> 32767 : 20 |*********** |
195+
32768 -> 65535 : 7 |*** |
196+
197+
This output sows that xvda1 has much higher latency, usually between 0.5 ms
198+
and 32 ms, whereas xvdc is usually between 0.2 ms and 4 ms.
199+
200+
139201
USAGE message:
140202

141203
# ./biolatency -h
142-
usage: biolatency [-h] [-T] [-Q] [-m] [interval] [count]
204+
usage: biolatency [-h] [-T] [-Q] [-m] [-D] [interval] [count]
143205

144206
Summarize block device I/O latency as a histogram
145207

@@ -152,9 +214,11 @@ optional arguments:
152214
-T, --timestamp include timestamp on output
153215
-Q, --queued include OS queued time in I/O time
154216
-m, --milliseconds millisecond histogram
217+
-D, --disks print a histogram per disk device
155218

156219
examples:
157220
./biolatency # summarize block I/O latency as a histogram
158221
./biolatency 1 10 # print 1 second summaries, 10 times
159222
./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
160223
./biolatency -Q # include OS queued time in I/O time
224+
./biolatency -D # show each disk device separately

0 commit comments

Comments
 (0)