Skip to content

Commit

Permalink
biolatency: add -F for I/O flags (#2280)
Browse files Browse the repository at this point in the history 
biolatency: add -F for I/O flags
  • Loading branch information
@brendangregg @yonghong-song
brendangregg authored and yonghong-song committed Mar 20, 2019
1 parent c7736ee commit c6cded4
Show file tree
Hide file tree
Showing 3 changed files with 175 additions and 3 deletions.
5 changes: 4 additions & 1 deletion man/man8/biolatency.8
View file
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down
74 changes: 73 additions & 1 deletion tools/biolatency.py
View file
Expand Up @@ -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",
Expand All @@ -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,
Expand All @@ -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 = """
Expand All @@ -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
Expand Down Expand Up @@ -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',
Expand All @@ -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")
Expand All @@ -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
Expand Down
99 changes: 98 additions & 1 deletion tools/biolatency_example.txt
View file
Expand Up @@ -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

Expand All @@ -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

0 comments on commit c6cded4

Please sign in to comment.