From c6cded439f77d345d2ff132798f8dde00dbdc60a Mon Sep 17 00:00:00 2001 From: Brendan Gregg Date: Wed, 20 Mar 2019 09:32:20 -0700 Subject: [PATCH] biolatency: add -F for I/O flags (#2280) biolatency: add -F for I/O flags --- man/man8/biolatency.8 | 5 +- tools/biolatency.py | 74 ++++++++++++++++++++++++++- tools/biolatency_example.txt | 99 +++++++++++++++++++++++++++++++++++- 3 files changed, 175 insertions(+), 3 deletions(-) diff --git a/man/man8/biolatency.8 b/man/man8/biolatency.8 index 84d261e24c7a..7aa3dd897bb9 100644 --- a/man/man8/biolatency.8 +++ b/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 diff --git a/tools/biolatency.py b/tools/biolatency.py index a265c3182b41..86d99437094a 100755 --- a/tools/biolatency.py +++ b/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 diff --git a/tools/biolatency_example.txt b/tools/biolatency_example.txt index 5d39b7ec54cd..933d9a7fcfea 100644 --- a/tools/biolatency_example.txt +++ b/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,6 +310,7 @@ 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 @@ -222,3 +318,4 @@ examples: ./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