Skip to content

Commit 2188d23

Browse files
netedwardwuyonghong-song
netedwardwu
authored and
yonghong-song
committed
tools: Add funcinterval bcc tool.
Time interval between the same function as a histogram. Referenced from funclatency.
1 parent f3fbeb4 commit 2188d23

File tree

4 files changed

+459
-0
lines changed

4 files changed

+459
-0
lines changed

‎README.md

+1
Original file line numberDiff line numberDiff line change
@@ -115,6 +115,7 @@ pair of .c and .py files, and some are directories of files.
115115
- tools/[fileslower](tools/fileslower.py): Trace slow synchronous file reads and writes. [Examples](tools/fileslower_example.txt).
116116
- tools/[filetop](tools/filetop.py): File reads and writes by filename and process. Top for files. [Examples](tools/filetop_example.txt).
117117
- tools/[funccount](tools/funccount.py): Count kernel function calls. [Examples](tools/funccount_example.txt).
118+
- tools/[funcinterval](tools/funcinterval.py): Time interval between the same function as a histogram. [Examples](tools/funcinterval_example.txt).
118119
- tools/[funclatency](tools/funclatency.py): Time functions and show their latency distribution. [Examples](tools/funclatency_example.txt).
119120
- tools/[funcslower](tools/funcslower.py): Trace slow kernel or user function calls. [Examples](tools/funcslower_example.txt).
120121
- tools/[gethostlatency](tools/gethostlatency.py): Show latency for getaddrinfo/gethostbyname[2] calls. [Examples](tools/gethostlatency_example.txt).

‎man/man8/funcinterval.8

+115
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,115 @@
1+
.TH funcinterval 8 "2020-05-27" "USER COMMANDS"
2+
.SH NAME
3+
funcinterval \- Time interval between the same function, tracepoint as a histogram.
4+
.SH SYNOPSIS
5+
.B funcinterval [\-h] [\-p PID] [\-i INTERVAL] [\-d DURATION] [\-T] [\-u] [\-m] [\-v] pattern
6+
.SH DESCRIPTION
7+
This tool times interval between the same function as a histogram.
8+
9+
eBPF/bcc is very suitable for platform performance tuning.
10+
By funclatency, we can profile specific functions to know how latency
11+
this function costs. However, sometimes performance drop is not about the
12+
latency of function but the interval between function calls.
13+
funcinterval is born for this purpose.
14+
15+
This tool uses in-kernel eBPF maps for storing timestamps and the histogram,
16+
for efficiency.
17+
18+
WARNING: This uses dynamic tracing of (what can be many) functions, an
19+
activity that has had issues on some kernel versions (risk of panics or
20+
freezes). Test, and know what you are doing, before use.
21+
22+
Since this uses BPF, only the root user can use this tool.
23+
.SH REQUIREMENTS
24+
CONFIG_BPF and bcc.
25+
.SH OPTIONS
26+
pattern
27+
Function name.
28+
\-h
29+
Print usage message.
30+
.TP
31+
\-p PID
32+
Trace this process ID only.
33+
.TP
34+
\-i INTERVAL
35+
Print output every interval seconds.
36+
.TP
37+
\-d DURATION
38+
Total duration of trace, in seconds.
39+
.TP
40+
\-T
41+
Include timestamps on output.
42+
.TP
43+
\-u
44+
Output histogram in microseconds.
45+
.TP
46+
\-m
47+
Output histogram in milliseconds.
48+
.TP
49+
\-v
50+
Print the BPF program (for debugging purposes).
51+
.SH EXAMPLES
52+
.TP
53+
Time the interval of do_sys_open() kernel function as a histogram:
54+
#
55+
.B funcinterval do_sys_open
56+
.TP
57+
Time the interval of xhci_ring_ep_doorbell(), in microseconds:
58+
#
59+
.B funcinterval -u xhci_ring_ep_doorbell
60+
.TP
61+
Time the interval of do_nanosleep(), in milliseconds
62+
#
63+
.B funcinterval -m do_nanosleep
64+
.TP
65+
Output every 5 seconds, with timestamps:
66+
#
67+
.B funcinterval -mTi 5 vfs_read
68+
.TP
69+
Time process 181 only:
70+
#
71+
.B funcinterval -p 181 vfs_read
72+
.TP
73+
Time the interval of mm_vmscan_direct_reclaim_begin tracepoint:
74+
#
75+
.B funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin
76+
.SH FIELDS
77+
.TP
78+
necs
79+
Nanosecond range
80+
.TP
81+
usecs
82+
Microsecond range
83+
.TP
84+
msecs
85+
Millisecond range
86+
.TP
87+
count
88+
How many calls fell into this range
89+
.TP
90+
distribution
91+
An ASCII bar chart to visualize the distribution (count column)
92+
.SH OVERHEAD
93+
This traces kernel functions and maintains in-kernel timestamps and a histogram,
94+
which are asynchronously copied to user-space. While this method is very
95+
efficient, the rate of kernel functions can also be very high (>1M/sec), at
96+
which point the overhead is expected to be measurable. Measure in a test
97+
environment and understand overheads before use. You can also use funccount
98+
to measure the rate of kernel functions over a short duration, to set some
99+
expectations before use.
100+
.SH SOURCE
101+
This is from bcc.
102+
.IP
103+
https://github.com/iovisor/bcc
104+
.PP
105+
Also look in the bcc distribution for a companion _examples.txt file containing
106+
example usage, output, and commentary for this tool.
107+
.SH OS
108+
Linux
109+
.SH STABILITY
110+
Unstable - in development.
111+
.SH AUTHOR
112+
Edward Wu
113+
.SH SEE ALSO
114+
funclatency(8)
115+
funccount(8)

‎tools/funcinterval.py

+180
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,180 @@
1+
#!/usr/bin/python
2+
# @lint-avoid-python-3-compatibility-imports
3+
#
4+
# funcinterval Time interval between the same function, tracepoint
5+
# as a histogram.
6+
#
7+
# USAGE: funcinterval [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-v] pattern
8+
#
9+
# Run "funcinterval -h" for full usage.
10+
#
11+
# Copyright (c) 2020 Realtek, Inc.
12+
# Licensed under the Apache License, Version 2.0 (the "License")
13+
#
14+
# 03-Jun-2020 Edward Wu Referenced funclatency and created this.
15+
16+
from __future__ import print_function
17+
from bcc import BPF
18+
from time import sleep, strftime
19+
import argparse
20+
import signal
21+
22+
# arguments
23+
examples = """examples:
24+
# time the interval of do_sys_open()
25+
./funcinterval do_sys_open
26+
# time the interval of xhci_ring_ep_doorbell(), in microseconds
27+
./funcinterval -u xhci_ring_ep_doorbell
28+
# time the interval of do_nanosleep(), in milliseconds
29+
./funcinterval -m do_nanosleep
30+
# output every 5 seconds, with timestamps
31+
./funcinterval -mTi 5 vfs_read
32+
# time process 181 only
33+
./funcinterval -p 181 vfs_read
34+
# time the interval of mm_vmscan_direct_reclaim_begin tracepoint
35+
./funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin
36+
"""
37+
parser = argparse.ArgumentParser(
38+
description="Time interval and print latency as a histogram",
39+
formatter_class=argparse.RawDescriptionHelpFormatter,
40+
epilog=examples)
41+
parser.add_argument("-p", "--pid", type=int,
42+
help="trace this PID only")
43+
parser.add_argument("-i", "--interval", type=int,
44+
help="summary interval, in seconds")
45+
parser.add_argument("-d", "--duration", type=int,
46+
help="total duration of trace, in seconds")
47+
parser.add_argument("-T", "--timestamp", action="store_true",
48+
help="include timestamp on output")
49+
parser.add_argument("-u", "--microseconds", action="store_true",
50+
help="microsecond histogram")
51+
parser.add_argument("-m", "--milliseconds", action="store_true",
52+
help="millisecond histogram")
53+
parser.add_argument("-v", "--verbose", action="store_true",
54+
help="print the BPF program (for debugging purposes)")
55+
parser.add_argument("pattern",
56+
help="Function/Tracepoint name for tracing")
57+
parser.add_argument("--ebpf", action="store_true",
58+
help=argparse.SUPPRESS)
59+
args = parser.parse_args()
60+
if args.duration and not args.interval:
61+
args.interval = args.duration
62+
if not args.interval:
63+
args.interval = 99999999
64+
65+
def bail(error):
66+
print("Error: " + error)
67+
exit(1)
68+
69+
70+
parts = args.pattern.split(':')
71+
if len(parts) == 1:
72+
attach_type = "function"
73+
pattern = args.pattern
74+
elif len(parts) == 3:
75+
attach_type = "tracepoint"
76+
pattern = ':'.join(parts[1:])
77+
else:
78+
bail("unrecognized pattern format '%s'" % pattern)
79+
80+
# define BPF program
81+
bpf_text = """
82+
#include <uapi/linux/ptrace.h>
83+
84+
BPF_HASH(start, u32, u64, 1);
85+
BPF_HISTOGRAM(dist);
86+
87+
int trace_func_entry(struct pt_regs *ctx)
88+
{
89+
u64 pid_tgid = bpf_get_current_pid_tgid();
90+
u32 index = 0, tgid = pid_tgid >> 32;
91+
u64 *tsp, ts = bpf_ktime_get_ns(), delta;
92+
93+
FILTER
94+
tsp = start.lookup(&index);
95+
if (tsp == 0)
96+
goto out;
97+
98+
delta = ts - *tsp;
99+
FACTOR
100+
101+
// store as histogram
102+
dist.increment(bpf_log2l(delta));
103+
104+
out:
105+
start.update(&index, &ts);
106+
107+
return 0;
108+
}
109+
"""
110+
111+
# code substitutions
112+
if args.pid:
113+
bpf_text = bpf_text.replace('FILTER',
114+
'if (tgid != %d) { return 0; }' % args.pid)
115+
else:
116+
bpf_text = bpf_text.replace('FILTER', '')
117+
if args.milliseconds:
118+
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
119+
label = "msecs"
120+
elif args.microseconds:
121+
bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
122+
label = "usecs"
123+
else:
124+
bpf_text = bpf_text.replace('FACTOR', '')
125+
label = "nsecs"
126+
127+
if args.verbose or args.ebpf:
128+
print(bpf_text)
129+
if args.ebpf:
130+
exit()
131+
132+
# signal handler
133+
def signal_ignore(signal, frame):
134+
print()
135+
136+
137+
# load BPF program
138+
b = BPF(text=bpf_text)
139+
140+
if len(parts) == 1:
141+
b.attach_kprobe(event=pattern, fn_name="trace_func_entry")
142+
matched = b.num_open_kprobes()
143+
elif len(parts) == 3:
144+
b.attach_tracepoint(tp=pattern, fn_name="trace_func_entry")
145+
matched = b.num_open_tracepoints()
146+
147+
if matched == 0:
148+
print("0 %s matched by \"%s\". Exiting." % (attach_type, pattern))
149+
exit()
150+
151+
# header
152+
print("Tracing %s for \"%s\"... Hit Ctrl-C to end." %
153+
(attach_type, pattern))
154+
155+
exiting = 0 if args.interval else 1
156+
seconds = 0
157+
dist = b.get_table("dist")
158+
start = b.get_table("start")
159+
while (1):
160+
try:
161+
sleep(args.interval)
162+
seconds += args.interval
163+
except KeyboardInterrupt:
164+
exiting = 1
165+
# as cleanup can take many seconds, trap Ctrl-C:
166+
signal.signal(signal.SIGINT, signal_ignore)
167+
if args.duration and seconds >= args.duration:
168+
exiting = 1
169+
170+
print()
171+
if args.timestamp:
172+
print("%-8s\n" % strftime("%H:%M:%S"), end="")
173+
174+
dist.print_log2_hist(label)
175+
dist.clear()
176+
start.clear()
177+
178+
if exiting:
179+
print("Detaching...")
180+
exit()

0 commit comments

Comments
 (0)