biolatency -D

man/man8/biolatency.8

@@ -2,7 +2,7 @@
 .SH NAME
 biolatency \- Summarize block device I/O latency as a histogram.
 .SH SYNOPSIS
-.B biolatency [\-h] [\-T] [\-Q] [\-m] [interval [count]]
+.B biolatency [\-h] [\-T] [\-Q] [\-m] [\-D] [interval [count]]
 .SH DESCRIPTION
 biolatency traces block device I/O (disk I/O), and records the distribution
 of I/O latency (time). This is printed as a histogram either on Ctrl-C, or
@@ -30,6 +30,9 @@ Include timestamps on output.
 \-m
 Output histogram in milliseconds.
 .TP
+\-D
+Print a histogram per disk device.
+.TP
 interval
 Output interval, in seconds.
 .TP
@@ -53,6 +56,10 @@ include timestamps on output:
 Include OS queued time in I/O time:
 #
 .B biolatency \-Q
+.TP
+Show a latency histogram for each disk device separately:
+#
+.B biolatency \-D
 .SH FIELDS
 .TP
 usecs

tools/biolatency

@@ -3,7 +3,7 @@
 # biolatency Summarize block device I/O latency as a histogram.
 # For Linux, uses BCC, eBPF.
 #
-# USAGE: biolatency [-h] [-T] [-Q] [-m] [interval] [count]
+# USAGE: biolatency [-h] [-T] [-Q] [-m] [-D] [interval] [count]
 #
 # Copyright (c) 2015 Brendan Gregg.
 # Licensed under the Apache License, Version 2.0 (the "License")
@@ -21,6 +21,7 @@ examples = """examples:
  ./biolatency 1 10 # print 1 second summaries, 10 times
  ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
  ./biolatency -Q # include OS queued time in I/O time
+ ./biolatency -D # show each disk device separately
 """
 parser = argparse.ArgumentParser(
  description="Summarize block device I/O latency as a histogram",
@@ -32,6 +33,8 @@ parser.add_argument("-Q", "--queued", action="store_true",
  help="include OS queued time in I/O time")
 parser.add_argument("-m", "--milliseconds", action="store_true",
  help="millisecond histogram")
+parser.add_argument("-D", "--disks", action="store_true",
+ help="print a histogram per disk device")
 parser.add_argument("interval", nargs="?", default=99999999,
  help="output interval, in seconds")
 parser.add_argument("count", nargs="?", default=99999999,
@@ -40,13 +43,17 @@ args = parser.parse_args()
 countdown = int(args.count)
 debug = 0
 
-# load BPF program
+# define BPF program
 bpf_text = """
 #include <uapi/linux/ptrace.h>
 #include <linux/blkdev.h>
 
-BPF_HISTOGRAM(dist);
+typedef struct disk_key {
+ char disk[DISK_NAME_LEN];
+ u64 slot;
+} disk_key_t;
 BPF_HASH(start, struct request *);
+STORAGE
 
 // time block I/O
 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)
  FACTOR
 
  // store as histogram
- dist.increment(bpf_log2l(delta));
+ STORE
 
  start.delete(&req);
  return 0;
 }
 """
+
+# code substitutions
 if args.milliseconds:
  bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
  label = "msecs"
 else:
  bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
  label = "usecs"
+if args.disks:
+ bpf_text = bpf_text.replace('STORAGE',
+ 'BPF_HISTOGRAM(dist, disk_key_t);')
+ bpf_text = bpf_text.replace('STORE',
+ 'disk_key_t key = {.slot = bpf_log2l(delta)}; ' +
+ 'bpf_probe_read(&key.disk, sizeof(key.disk), ' +
+ 'req->rq_disk->disk_name); dist.increment(key);')
+else:
+ bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);')
+ bpf_text = bpf_text.replace('STORE',
+ 'dist.increment(bpf_log2l(delta));')
 if debug:
  print(bpf_text)
 
@@ -110,7 +130,7 @@ while (1):
  if args.timestamp:
  print("%-8s\n" % strftime("%H:%M:%S"), end="")
 
- dist.print_log2_hist(label)
+ dist.print_log2_hist(label, "disk")
  dist.clear()
 
  countdown -= 1

tools/biolatency_example.txt

@@ -136,10 +136,72 @@ queues of their own, which are always included in the latency, with or
 without -Q.
 
 
+The -D option will print a histogram per disk. Eg:
+
+# ./biolatency -D
+Tracing block device I/O... Hit Ctrl-C to end.
+^C
+
+Bucket disk = 'xvdb'
+ usecs : count distribution
+ 0 -> 1 : 0 | |
+ 2 -> 3 : 0 | |
+ 4 -> 7 : 0 | |
+ 8 -> 15 : 0 | |
+ 16 -> 31 : 0 | |
+ 32 -> 63 : 0 | |
+ 64 -> 127 : 0 | |
+ 128 -> 255 : 1 | |
+ 256 -> 511 : 33 |********************** |
+ 512 -> 1023 : 36 |************************ |
+ 1024 -> 2047 : 58 |****************************************|
+ 2048 -> 4095 : 51 |*********************************** |
+ 4096 -> 8191 : 21 |************** |
+ 8192 -> 16383 : 2 |* |
+
+Bucket disk = 'xvdc'
+ usecs : count distribution
+ 0 -> 1 : 0 | |
+ 2 -> 3 : 0 | |
+ 4 -> 7 : 0 | |
+ 8 -> 15 : 0 | |
+ 16 -> 31 : 0 | |
+ 32 -> 63 : 0 | |
+ 64 -> 127 : 0 | |
+ 128 -> 255 : 1 | |
+ 256 -> 511 : 38 |*********************** |
+ 512 -> 1023 : 42 |************************* |
+ 1024 -> 2047 : 66 |****************************************|
+ 2048 -> 4095 : 40 |************************ |
+ 4096 -> 8191 : 14 |******** |
+
+Bucket disk = 'xvda1'
+ usecs : count distribution
+ 0 -> 1 : 0 | |
+ 2 -> 3 : 0 | |
+ 4 -> 7 : 0 | |
+ 8 -> 15 : 0 | |
+ 16 -> 31 : 0 | |
+ 32 -> 63 : 0 | |
+ 64 -> 127 : 0 | |
+ 128 -> 255 : 0 | |
+ 256 -> 511 : 18 |********** |
+ 512 -> 1023 : 67 |************************************* |
+ 1024 -> 2047 : 35 |******************* |
+ 2048 -> 4095 : 71 |****************************************|
+ 4096 -> 8191 : 65 |************************************ |
+ 8192 -> 16383 : 65 |************************************ |
+ 16384 -> 32767 : 20 |*********** |
+ 32768 -> 65535 : 7 |*** |
+
+This output sows that xvda1 has much higher latency, usually between 0.5 ms
+and 32 ms, whereas xvdc is usually between 0.2 ms and 4 ms.
+
+
 USAGE message:
 
 # ./biolatency -h
-usage: biolatency [-h] [-T] [-Q] [-m] [interval] [count]
+usage: biolatency [-h] [-T] [-Q] [-m] [-D] [interval] [count]
 
 Summarize block device I/O latency as a histogram
 
@@ -152,9 +214,11 @@ optional arguments:
  -T, --timestamp include timestamp on output
  -Q, --queued include OS queued time in I/O time
  -m, --milliseconds millisecond histogram
+ -D, --disks print a histogram per disk device
 
 examples:
  ./biolatency # summarize block I/O latency as a histogram
  ./biolatency 1 10 # print 1 second summaries, 10 times
  ./biolatency -mT 1 # 1s summaries, milliseconds, and timestamps
  ./biolatency -Q # include OS queued time in I/O time
+ ./biolatency -D # show each disk device separately