Repository navigation
Expand file tree
/
Copy pathfunclatency
More file actions
executable file
·187 lines (167 loc) · 5.39 KB
/
Copy pathfunclatency
File metadata and controls
executable file
·187 lines (167 loc) · 5.39 KB
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
#!/usr/bin/python
#
# funclatency Time kernel funcitons and print latency as a histogram.
# For Linux, uses BCC, eBPF.
#
# USAGE: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-r] pattern
#
# Run "funclatency -h" for full usage.
#
# The pattern is a string with optional '*' wildcards, similar to file globbing.
# If you'd prefer to use regular expressions, use the -r option. Matching
# 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")
#
# 20-Sep-2015 Brendan Gregg Created this.
from __future__ import print_function
from bcc import BPF
from time import sleep, strftime
import argparse
import signal
# arguments
examples = """examples:
./funclatency do_sys_open # time the do_sys_open() kenel function
./funclatency -u vfs_read # time vfs_read(), in microseconds
./funclatency -m do_nanosleep # time do_nanosleep(), in milliseconds
./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",
formatter_class=argparse.RawDescriptionHelpFormatter,
epilog=examples)
parser.add_argument("-p", "--pid",
help="trace this PID only")
parser.add_argument("-i", "--interval", default=99999999,
help="summary interval, seconds")
parser.add_argument("-T", "--timestamp", action="store_true",
help="include timestamp on output")
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",
help="search expression for kernel functions")
args = parser.parse_args()
pattern = args.pattern
if not args.regexp:
pattern = pattern.replace('*', '.*')
pattern = '^' + pattern + '$'
debug = 0
# define BPF program
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);
STORAGE
int trace_func_entry(struct pt_regs *ctx)
{
u32 pid = bpf_get_current_pid_tgid();
u64 ts = bpf_ktime_get_ns();
FILTER
ENTRYSTORE
start.update(&pid, &ts);
return 0;
}
int trace_func_return(struct pt_regs *ctx)
{
u64 *tsp, delta;
u32 pid = bpf_get_current_pid_tgid();
// calculate delta time
tsp = start.lookup(&pid);
if (tsp == 0) {
return 0; // missed start
}
delta = bpf_ktime_get_ns() - *tsp;
start.delete(&pid);
FACTOR
// store as histogram
STORE
return 0;
}
"""
# code substitutions
if args.pid:
bpf_text = bpf_text.replace('FILTER',
'if (pid != %s) { return 0; }' % args.pid)
else:
bpf_text = bpf_text.replace('FILTER', '')
if args.milliseconds:
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
label = "msecs"
elif args.microseconds:
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
label = "usecs"
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)
# signal handler
def signal_ignore(signal, frame):
print()
# load BPF program
b = BPF(text=bpf_text)
b.attach_kprobe(event_re=pattern, fn_name="trace_func_entry")
b.attach_kretprobe(event_re=pattern, fn_name="trace_func_return")
matched = b.num_open_kprobes()
if matched == 0:
print("0 functions matched by \"%s\". Exiting." % args.pattern)
exit()
# header
print("Tracing %d functions for \"%s\"... Hit Ctrl-C to end." %
(matched / 2, args.pattern))
# output
exiting = 0 if args.interval else 1
dist = b.get_table("dist")
while (1):
try:
sleep(int(args.interval))
except KeyboardInterrupt:
exiting=1
# as cleanup can take many seconds, trap Ctrl-C:
signal.signal(signal.SIGINT, signal_ignore)
print()
if args.timestamp:
print("%-8s\n" % strftime("%H:%M:%S"), end="")
if args.function:
dist.print_log2_hist(label, "Function", BPF.ksym)
else:
dist.print_log2_hist(label)
dist.clear()
if exiting:
print("Detaching...")
exit()