diff --git a/man/man8/biolatency.8 b/man/man8/biolatency.8 index 8f0156d9eea6..2cb09085b7ce 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] [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 diff --git a/tools/biolatency b/tools/biolatency index 851a2545c9af..3b1466712d84 100755 --- a/tools/biolatency +++ b/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 #include -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 diff --git a/tools/biolatency_example.txt b/tools/biolatency_example.txt index 9431ea92931e..06944c0a47e1 100644 --- a/tools/biolatency_example.txt +++ b/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