Skip to content

B
bcc
Commit ebc8e7e7 authored by Brenden Blanco's avatar Brenden Blanco
Browse files
Options

Merge pull request #250 from brendangregg/master 

begin using new histogram breakdowns feature
parents 919d30a0 44e68770
Hide whitespace changes
Inline Side-by-side
Showing with 208 additions and 13 deletions
man/man8/biolatency.8
View file @ ebc8e7e7
......@@ -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
......
man/man8/funclatency.8
View file @ ebc8e7e7
......@@ -2,7 +2,7 @@
.SH NAME
funclatency \- Time kernel funcitons and print latency as a histogram.
.SH SYNOPSIS
.B funclatency [\-h] [\-p PID] [\-i INTERVAL] [\-T] [\-u] [\-m] [\-r] pattern
.B funclatency [\-h] [\-p PID] [\-i INTERVAL] [\-T] [\-u] [\-m] [\-r] [\-F] pattern
.SH DESCRIPTION
This tool traces kernel function calls and times their duration (latency), and
shows the latency distribution as a histogram. The time is measured from when
......@@ -12,6 +12,11 @@ time and time spent blocked.
This tool uses in-kernel eBPF maps for storing timestamps and the histogram,
for efficiency.
Currently nested or recursive functions are not supported properly, and
timestamps will be overwritten, creating dubious output. Try to match single
functions, or groups of functions that run at the same stack layer, and
don't ultimately call each other.
WARNING: This uses dynamic tracing of (what can be many) kernel functions, an
activity that has had issues on some kernel versions (risk of panics or
freezes). Test, and know what you are doing, before use.
......@@ -41,6 +46,9 @@ Output histogram in microseconds.
\-m
Output histogram in milliseconds.
.TP
\-F
Print a separate histogram per function matched.
.TP
\-r
Use regular expressions for the search pattern.
.SH EXAMPLES
......@@ -68,6 +76,10 @@ Time vfs_read() for process ID 181 only:
Time both vfs_fstat() and vfs_fstatat() calls, by use of a wildcard:
#
.B funclatency 'vfs_fstat*'
.TP
Time both vfs_fstat* calls, and print a separate histogram for each:
#
.B funclatency -F 'vfs_fstat*'
.SH FIELDS
.TP
necs
......
tools/biolatency
View file @ ebc8e7e7
......@@ -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
View file @ ebc8e7e7
......@@ -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
tools/funclatency
View file @ ebc8e7e7
......@@ -12,6 +12,11 @@
# multiple functions is of limited use, since the output has one histogram for
# everything. Future versions should split the output histogram by the function.
#
# Currently nested or recursive functions are not supported properly, and
# timestamps will be overwritten, creating dubious output. Try to match single
# functions, or groups of functions that run at the same stack layer, and
# don't ultimately call each other.
#
# Copyright (c) 2015 Brendan Gregg.
# Licensed under the Apache License, Version 2.0 (the "License")
#
......@@ -31,6 +36,7 @@ examples = """examples:
./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps
./funclatency -p 181 vfs_read # time process 181 only
./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat()
./funclatency -F 'vfs_r*' # show one histogram per matched function
"""
parser = argparse.ArgumentParser(
description="Time kernel funcitons and print latency as a histogram",
......@@ -46,6 +52,8 @@ parser.add_argument("-u", "--microseconds", action="store_true",
help="microsecond histogram")
parser.add_argument("-m", "--milliseconds", action="store_true",
help="millisecond histogram")
parser.add_argument("-F", "--function", action="store_true",
help="show a separate histogram per function")
parser.add_argument("-r", "--regexp", action="store_true",
help="use regular expressions. Default is \"*\" wildcards only.")
parser.add_argument("pattern",
......@@ -62,8 +70,13 @@ bpf_text = """
#include <uapi/linux/ptrace.h>
#include <linux/blkdev.h>
typedef struct ip_key {
u64 ip;
u64 slot;
} ip_key_t;
BPF_HASH(start, u32);
BPF_HISTOGRAM(dist);
STORAGE
int trace_func_entry(struct pt_regs *ctx)
{
......@@ -71,6 +84,7 @@ int trace_func_entry(struct pt_regs *ctx)
u64 ts = bpf_ktime_get_ns();
FILTER
ENTRYSTORE
start.update(&pid, &ts);
return 0;
......@@ -91,11 +105,13 @@ int trace_func_return(struct pt_regs *ctx)
FACTOR
// store as histogram
dist.increment(bpf_log2l(delta));
STORE
return 0;
}
"""
# code substitutions
if args.pid:
bpf_text = bpf_text.replace('FILTER',
'if (pid != %s) { return 0; }' % args.pid)
......@@ -110,6 +126,21 @@ elif args.microseconds:
else:
bpf_text = bpf_text.replace('FACTOR', '')
label = "nsecs"
if args.function:
bpf_text = bpf_text.replace('STORAGE', 'BPF_HASH(ipaddr, u32);\n' +
'BPF_HISTOGRAM(dist, ip_key_t);')
# stash the IP on entry, as on return it's kretprobe_trampoline:
bpf_text = bpf_text.replace('ENTRYSTORE',
'u64 ip = ctx->ip; ipaddr.update(&pid, &ip);')
bpf_text = bpf_text.replace('STORE',
'u64 ip, *ipp = ipaddr.lookup(&pid); if (ipp) { ip = *ipp; ' +
'dist.increment((ip_key_t){ip, bpf_log2l(delta)}); ' +
'ipaddr.delete(&pid); }')
else:
bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);')
bpf_text = bpf_text.replace('ENTRYSTORE', '')
bpf_text = bpf_text.replace('STORE',
'dist.increment(bpf_log2l(delta));')
if debug:
print(bpf_text)
......@@ -130,6 +161,20 @@ if matched == 0:
print("Tracing %d functions for \"%s\"... Hit Ctrl-C to end." %
(matched / 2, args.pattern))
# custom output (from __init__.py)
def print_log2_hist_byfunc(self, val_type="value"):
tmp = {}
f1 = self.Key._fields_[0][0]
f2 = self.Key._fields_[1][0]
for k, v in self.items():
bucket = getattr(k, f1)
vals = tmp[bucket] = tmp.get(bucket, [0] * 65)
slot = getattr(k, f2)
vals[slot] = v.value
for bucket, vals in tmp.items():
print("\nFunction = %s" % BPF.ksym(bucket))
self._print_log2_hist(vals, val_type, 0)
# output
exiting = 0 if args.interval else 1
dist = b.get_table("dist")
......@@ -145,7 +190,10 @@ while (1):
if args.timestamp:
print("%-8s\n" % strftime("%H:%M:%S"), end="")
dist.print_log2_hist(label)
if args.function:
print_log2_hist_byfunc(dist, label)
else:
dist.print_log2_hist(label)
dist.clear()
if exiting:
......
tools/funclatency_example.txt
View file @ ebc8e7e7
......@@ -195,10 +195,52 @@ Detaching...
The distribution between 64 and 511 milliseconds shows keystroke latency.
The -F option can be used to print a histogram per function. Eg:
# ./funclatency -uF 'vfs_r*'
Tracing 5 functions for "vfs_r*"... Hit Ctrl-C to end.
^C
Function = vfs_read
usecs : count distribution
0 -> 1 : 1044 |****************************************|
2 -> 3 : 383 |************** |
4 -> 7 : 76 |** |
8 -> 15 : 41 |* |
16 -> 31 : 26 | |
32 -> 63 : 0 | |
64 -> 127 : 1 | |
128 -> 255 : 0 | |
256 -> 511 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 4 | |
4096 -> 8191 : 2 | |
8192 -> 16383 : 0 | |
16384 -> 32767 : 0 | |
32768 -> 65535 : 2 | |
65536 -> 131071 : 5 | |
131072 -> 262143 : 5 | |
262144 -> 524287 : 3 | |
524288 -> 1048575 : 7 | |
Function = vfs_rename
usecs : count distribution
0 -> 1 : 2 |**** |
2 -> 3 : 2 |**** |
4 -> 7 : 2 |**** |
8 -> 15 : 0 | |
16 -> 31 : 6 |************* |
32 -> 63 : 18 |****************************************|
Detaching...
USAGE message:
# ./funclatency -h
usage: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-r] pattern
# ./funclatency -h
usage: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-F] [-r]
pattern
Time kernel funcitons and print latency as a histogram
......@@ -213,6 +255,7 @@ optional arguments:
-T, --timestamp include timestamp on output
-u, --microseconds microsecond histogram
-m, --milliseconds millisecond histogram
-F, --function show a separate histogram per function
-r, --regexp use regular expressions. Default is "*" wildcards
only.
......@@ -223,3 +266,4 @@ examples:
./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps
./funclatency -p 181 vfs_read # time process 181 only
./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat()
./funclatency -F 'vfs_r*' # show one histogram per matched function
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment
GitLab Nexedi Edition | About GitLab | About Nexedi | 沪ICP备2021021310号-2 | 沪ICP备2021021310号-7