biolatency: add -F for I/O flags

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] [\-D] [interval [count]]
+.B biolatency [\-h] [\-F] [\-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
@@ -33,6 +33,9 @@ Output histogram in milliseconds.
 \-D
 Print a histogram per disk device.
 .TP
+\-F
+Print a histogram per set of I/O flags.
+.TP
 interval
 Output interval, in seconds.
 .TP

tools/biolatency.py

@@ -23,6 +23,7 @@
     ./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
+    ./biolatency -F         # show I/O flags separately
 """
 parser = argparse.ArgumentParser(
     description="Summarize block device I/O latency as a histogram",
@@ -36,6 +37,8 @@
     help="millisecond histogram")
 parser.add_argument("-D", "--disks", action="store_true",
     help="print a histogram per disk device")
+parser.add_argument("-F", "--flags", action="store_true",
+    help="print a histogram per set of I/O flags")
 parser.add_argument("interval", nargs="?", default=99999999,
     help="output interval, in seconds")
 parser.add_argument("count", nargs="?", default=99999999,
@@ -45,6 +48,9 @@
 args = parser.parse_args()
 countdown = int(args.count)
 debug = 0
+if args.flags and args.disks:
+    print("ERROR: can only use -D or -F. Exiting.")
+    exit()
 
 # define BPF program
 bpf_text = """
@@ -55,6 +61,12 @@
     char disk[DISK_NAME_LEN];
     u64 slot;
 } disk_key_t;
+
+typedef struct flag_key {
+    u64 flags;
+    u64 slot;
+} flag_key_t;
+
 BPF_HASH(start, struct request *);
 STORAGE
 
@@ -102,6 +114,13 @@
         'void *__tmp = (void *)req->rq_disk->disk_name; ' +
         'bpf_probe_read(&key.disk, sizeof(key.disk), __tmp); ' +
         'dist.increment(key);')
+elif args.flags:
+    bpf_text = bpf_text.replace('STORAGE',
+        'BPF_HISTOGRAM(dist, flag_key_t);')
+    bpf_text = bpf_text.replace('STORE',
+        'flag_key_t key = {.slot = bpf_log2l(delta)}; ' +
+        'key.flags = req->cmd_flags; ' +
+        'dist.increment(key);')
 else:
     bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);')
     bpf_text = bpf_text.replace('STORE',
@@ -124,6 +143,56 @@
 
 print("Tracing block device I/O... Hit Ctrl-C to end.")
 
+# see blk_fill_rwbs():
+req_opf = {
+    0: "Read",
+    1: "Write",
+    2: "Flush",
+    3: "Discard",
+    5: "SecureErase",
+    6: "ZoneReset",
+    7: "WriteSame",
+    9: "WriteZeros"
+}
+REQ_OP_BITS = 8
+REQ_OP_MASK = ((1 << REQ_OP_BITS) - 1)
+REQ_SYNC = 1 << (REQ_OP_BITS + 3)
+REQ_META = 1 << (REQ_OP_BITS + 4)
+REQ_PRIO = 1 << (REQ_OP_BITS + 5)
+REQ_NOMERGE = 1 << (REQ_OP_BITS + 6)
+REQ_IDLE = 1 << (REQ_OP_BITS + 7)
+REQ_FUA = 1 << (REQ_OP_BITS + 9)
+REQ_RAHEAD = 1 << (REQ_OP_BITS + 11)
+REQ_BACKGROUND = 1 << (REQ_OP_BITS + 12)
+REQ_NOWAIT = 1 << (REQ_OP_BITS + 13)
+def flags_print(flags):
+    desc = ""
+    # operation
+    if flags & REQ_OP_MASK in req_opf:
+        desc = req_opf[flags & REQ_OP_MASK]
+    else:
+        desc = "Unknown"
+    # flags
+    if flags & REQ_SYNC:
+        desc = "Sync-" + desc
+    if flags & REQ_META:
+        desc = "Metadata-" + desc
+    if flags & REQ_FUA:
+        desc = "ForcedUnitAccess-" + desc
+    if flags & REQ_PRIO:
+        desc = "Priority-" + desc
+    if flags & REQ_NOMERGE:
+        desc = "NoMerge-" + desc
+    if flags & REQ_IDLE:
+        desc = "Idle-" + desc
+    if flags & REQ_RAHEAD:
+        desc = "ReadAhead-" + desc
+    if flags & REQ_BACKGROUND:
+        desc = "Background-" + desc
+    if flags & REQ_NOWAIT:
+        desc = "NoWait-" + desc
+    return desc
+
 # output
 exiting = 0 if args.interval else 1
 dist = b.get_table("dist")
@@ -137,7 +206,10 @@
     if args.timestamp:
         print("%-8s\n" % strftime("%H:%M:%S"), end="")
 
-    dist.print_log2_hist(label, "disk")
+    if args.flags:
+        dist.print_log2_hist(label, "flags", flags_print)
+    else:
+        dist.print_log2_hist(label, "disk")
     dist.clear()
 
     countdown -= 1

tools/biolatency_example.txt

@@ -198,10 +198,105 @@ 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.
 
 
+The -F option prints a separate histogram for each unique set of request
+flags. For example:
+
+./biolatency.py -Fm
+Tracing block device I/O... Hit Ctrl-C to end.
+^C
+
+flags = Read
+     msecs               : count     distribution
+         0 -> 1          : 180      |*************                           |
+         2 -> 3          : 519      |****************************************|
+         4 -> 7          : 60       |****                                    |
+         8 -> 15         : 123      |*********                               |
+        16 -> 31         : 68       |*****                                   |
+        32 -> 63         : 0        |                                        |
+        64 -> 127        : 2        |                                        |
+       128 -> 255        : 12       |                                        |
+       256 -> 511        : 0        |                                        |
+       512 -> 1023       : 1        |                                        |
+
+flags = Sync-Write
+     msecs               : count     distribution
+         0 -> 1          : 5        |****************************************|
+
+flags = Flush
+     msecs               : count     distribution
+         0 -> 1          : 2        |****************************************|
+
+flags = Metadata-Read
+     msecs               : count     distribution
+         0 -> 1          : 3        |****************************************|
+         2 -> 3          : 2        |**************************              |
+         4 -> 7          : 0        |                                        |
+         8 -> 15         : 1        |*************                           |
+        16 -> 31         : 1        |*************                           |
+
+flags = Write
+     msecs               : count     distribution
+         0 -> 1          : 103      |*******************************         |
+         2 -> 3          : 106      |********************************        |
+         4 -> 7          : 130      |****************************************|
+         8 -> 15         : 79       |************************                |
+        16 -> 31         : 5        |*                                       |
+        32 -> 63         : 0        |                                        |
+        64 -> 127        : 0        |                                        |
+       128 -> 255        : 0        |                                        |
+       256 -> 511        : 1        |                                        |
+
+flags = NoMerge-Read
+     msecs               : count     distribution
+         0 -> 1          : 0        |                                        |
+         2 -> 3          : 5        |****************************************|
+         4 -> 7          : 0        |                                        |
+         8 -> 15         : 0        |                                        |
+        16 -> 31         : 1        |********                                |
+
+flags = NoMerge-Write
+     msecs               : count     distribution
+         0 -> 1          : 30       |**                                      |
+         2 -> 3          : 293      |********************                    |
+         4 -> 7          : 564      |****************************************|
+         8 -> 15         : 463      |********************************        |
+        16 -> 31         : 21       |*                                       |
+        32 -> 63         : 0        |                                        |
+        64 -> 127        : 0        |                                        |
+       128 -> 255        : 0        |                                        |
+       256 -> 511        : 5        |                                        |
+
+flags = Priority-Metadata-Read
+     msecs               : count     distribution
+         0 -> 1          : 1        |****************************************|
+         2 -> 3          : 0        |                                        |
+         4 -> 7          : 1        |****************************************|
+         8 -> 15         : 1        |****************************************|
+
+flags = ForcedUnitAccess-Metadata-Sync-Write
+     msecs               : count     distribution
+         0 -> 1          : 2        |****************************************|
+
+flags = ReadAhead-Read
+     msecs               : count     distribution
+         0 -> 1          : 15       |***************************             |
+         2 -> 3          : 22       |****************************************|
+         4 -> 7          : 14       |*************************               |
+         8 -> 15         : 8        |**************                          |
+        16 -> 31         : 1        |*                                       |
+
+flags = Priority-Metadata-Write
+     msecs               : count     distribution
+         0 -> 1          : 9        |****************************************|
+
+These can be handled differently by the storage device, and this mode lets us
+examine their performance in isolation.
+
+
 USAGE message:
 
 # ./biolatency -h
-usage: biolatency [-h] [-T] [-Q] [-m] [-D] [interval] [count]
+usage: biolatency [-h] [-T] [-Q] [-m] [-D] [-F] [interval] [count]
 
 Summarize block device I/O latency as a histogram
 
@@ -215,10 +310,12 @@ optional arguments:
   -Q, --queued        include OS queued time in I/O time
   -m, --milliseconds  millisecond histogram
   -D, --disks         print a histogram per disk device
+  -F, --flags         print a histogram per set of I/O flags
 
 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
+    ./biolatency -F         # show I/O flags separately