forked from iovisor/bcc
-
Notifications
You must be signed in to change notification settings - Fork 0
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Time interval between the same function as a histogram. Referenced from funclatency.
- Loading branch information
1 parent
f3fbeb4
commit 2188d23
Showing
4 changed files
with
459 additions
and
0 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,115 @@ | ||
.TH funcinterval 8 "2020-05-27" "USER COMMANDS" | ||
.SH NAME | ||
funcinterval \- Time interval between the same function, tracepoint as a histogram. | ||
.SH SYNOPSIS | ||
.B funcinterval [\-h] [\-p PID] [\-i INTERVAL] [\-d DURATION] [\-T] [\-u] [\-m] [\-v] pattern | ||
.SH DESCRIPTION | ||
This tool times interval between the same function as a histogram. | ||
|
||
eBPF/bcc is very suitable for platform performance tuning. | ||
By funclatency, we can profile specific functions to know how latency | ||
this function costs. However, sometimes performance drop is not about the | ||
latency of function but the interval between function calls. | ||
funcinterval is born for this purpose. | ||
|
||
This tool uses in-kernel eBPF maps for storing timestamps and the histogram, | ||
for efficiency. | ||
|
||
WARNING: This uses dynamic tracing of (what can be many) 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. | ||
|
||
Since this uses BPF, only the root user can use this tool. | ||
.SH REQUIREMENTS | ||
CONFIG_BPF and bcc. | ||
.SH OPTIONS | ||
pattern | ||
Function name. | ||
\-h | ||
Print usage message. | ||
.TP | ||
\-p PID | ||
Trace this process ID only. | ||
.TP | ||
\-i INTERVAL | ||
Print output every interval seconds. | ||
.TP | ||
\-d DURATION | ||
Total duration of trace, in seconds. | ||
.TP | ||
\-T | ||
Include timestamps on output. | ||
.TP | ||
\-u | ||
Output histogram in microseconds. | ||
.TP | ||
\-m | ||
Output histogram in milliseconds. | ||
.TP | ||
\-v | ||
Print the BPF program (for debugging purposes). | ||
.SH EXAMPLES | ||
.TP | ||
Time the interval of do_sys_open() kernel function as a histogram: | ||
# | ||
.B funcinterval do_sys_open | ||
.TP | ||
Time the interval of xhci_ring_ep_doorbell(), in microseconds: | ||
# | ||
.B funcinterval -u xhci_ring_ep_doorbell | ||
.TP | ||
Time the interval of do_nanosleep(), in milliseconds | ||
# | ||
.B funcinterval -m do_nanosleep | ||
.TP | ||
Output every 5 seconds, with timestamps: | ||
# | ||
.B funcinterval -mTi 5 vfs_read | ||
.TP | ||
Time process 181 only: | ||
# | ||
.B funcinterval -p 181 vfs_read | ||
.TP | ||
Time the interval of mm_vmscan_direct_reclaim_begin tracepoint: | ||
# | ||
.B funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin | ||
.SH FIELDS | ||
.TP | ||
necs | ||
Nanosecond range | ||
.TP | ||
usecs | ||
Microsecond range | ||
.TP | ||
msecs | ||
Millisecond range | ||
.TP | ||
count | ||
How many calls fell into this range | ||
.TP | ||
distribution | ||
An ASCII bar chart to visualize the distribution (count column) | ||
.SH OVERHEAD | ||
This traces kernel functions and maintains in-kernel timestamps and a histogram, | ||
which are asynchronously copied to user-space. While this method is very | ||
efficient, the rate of kernel functions can also be very high (>1M/sec), at | ||
which point the overhead is expected to be measurable. Measure in a test | ||
environment and understand overheads before use. You can also use funccount | ||
to measure the rate of kernel functions over a short duration, to set some | ||
expectations before use. | ||
.SH SOURCE | ||
This is from bcc. | ||
.IP | ||
https://github.com/iovisor/bcc | ||
.PP | ||
Also look in the bcc distribution for a companion _examples.txt file containing | ||
example usage, output, and commentary for this tool. | ||
.SH OS | ||
Linux | ||
.SH STABILITY | ||
Unstable - in development. | ||
.SH AUTHOR | ||
Edward Wu | ||
.SH SEE ALSO | ||
funclatency(8) | ||
funccount(8) |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Original file line number | Diff line number | Diff line change |
---|---|---|
@@ -0,0 +1,180 @@ | ||
#!/usr/bin/python | ||
# @lint-avoid-python-3-compatibility-imports | ||
# | ||
# funcinterval Time interval between the same function, tracepoint | ||
# as a histogram. | ||
# | ||
# USAGE: funcinterval [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-v] pattern | ||
# | ||
# Run "funcinterval -h" for full usage. | ||
# | ||
# Copyright (c) 2020 Realtek, Inc. | ||
# Licensed under the Apache License, Version 2.0 (the "License") | ||
# | ||
# 03-Jun-2020 Edward Wu Referenced funclatency and created this. | ||
|
||
from __future__ import print_function | ||
from bcc import BPF | ||
from time import sleep, strftime | ||
import argparse | ||
import signal | ||
|
||
# arguments | ||
examples = """examples: | ||
# time the interval of do_sys_open() | ||
./funcinterval do_sys_open | ||
# time the interval of xhci_ring_ep_doorbell(), in microseconds | ||
./funcinterval -u xhci_ring_ep_doorbell | ||
# time the interval of do_nanosleep(), in milliseconds | ||
./funcinterval -m do_nanosleep | ||
# output every 5 seconds, with timestamps | ||
./funcinterval -mTi 5 vfs_read | ||
# time process 181 only | ||
./funcinterval -p 181 vfs_read | ||
# time the interval of mm_vmscan_direct_reclaim_begin tracepoint | ||
./funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin | ||
""" | ||
parser = argparse.ArgumentParser( | ||
description="Time interval and print latency as a histogram", | ||
formatter_class=argparse.RawDescriptionHelpFormatter, | ||
epilog=examples) | ||
parser.add_argument("-p", "--pid", type=int, | ||
help="trace this PID only") | ||
parser.add_argument("-i", "--interval", type=int, | ||
help="summary interval, in seconds") | ||
parser.add_argument("-d", "--duration", type=int, | ||
help="total duration of trace, in 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("-v", "--verbose", action="store_true", | ||
help="print the BPF program (for debugging purposes)") | ||
parser.add_argument("pattern", | ||
help="Function/Tracepoint name for tracing") | ||
parser.add_argument("--ebpf", action="store_true", | ||
help=argparse.SUPPRESS) | ||
args = parser.parse_args() | ||
if args.duration and not args.interval: | ||
args.interval = args.duration | ||
if not args.interval: | ||
args.interval = 99999999 | ||
|
||
def bail(error): | ||
print("Error: " + error) | ||
exit(1) | ||
|
||
|
||
parts = args.pattern.split(':') | ||
if len(parts) == 1: | ||
attach_type = "function" | ||
pattern = args.pattern | ||
elif len(parts) == 3: | ||
attach_type = "tracepoint" | ||
pattern = ':'.join(parts[1:]) | ||
else: | ||
bail("unrecognized pattern format '%s'" % pattern) | ||
|
||
# define BPF program | ||
bpf_text = """ | ||
#include <uapi/linux/ptrace.h> | ||
BPF_HASH(start, u32, u64, 1); | ||
BPF_HISTOGRAM(dist); | ||
int trace_func_entry(struct pt_regs *ctx) | ||
{ | ||
u64 pid_tgid = bpf_get_current_pid_tgid(); | ||
u32 index = 0, tgid = pid_tgid >> 32; | ||
u64 *tsp, ts = bpf_ktime_get_ns(), delta; | ||
FILTER | ||
tsp = start.lookup(&index); | ||
if (tsp == 0) | ||
goto out; | ||
delta = ts - *tsp; | ||
FACTOR | ||
// store as histogram | ||
dist.increment(bpf_log2l(delta)); | ||
out: | ||
start.update(&index, &ts); | ||
return 0; | ||
} | ||
""" | ||
|
||
# code substitutions | ||
if args.pid: | ||
bpf_text = bpf_text.replace('FILTER', | ||
'if (tgid != %d) { 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.verbose or args.ebpf: | ||
print(bpf_text) | ||
if args.ebpf: | ||
exit() | ||
|
||
# signal handler | ||
def signal_ignore(signal, frame): | ||
print() | ||
|
||
|
||
# load BPF program | ||
b = BPF(text=bpf_text) | ||
|
||
if len(parts) == 1: | ||
b.attach_kprobe(event=pattern, fn_name="trace_func_entry") | ||
matched = b.num_open_kprobes() | ||
elif len(parts) == 3: | ||
b.attach_tracepoint(tp=pattern, fn_name="trace_func_entry") | ||
matched = b.num_open_tracepoints() | ||
|
||
if matched == 0: | ||
print("0 %s matched by \"%s\". Exiting." % (attach_type, pattern)) | ||
exit() | ||
|
||
# header | ||
print("Tracing %s for \"%s\"... Hit Ctrl-C to end." % | ||
(attach_type, pattern)) | ||
|
||
exiting = 0 if args.interval else 1 | ||
seconds = 0 | ||
dist = b.get_table("dist") | ||
start = b.get_table("start") | ||
while (1): | ||
try: | ||
sleep(args.interval) | ||
seconds += args.interval | ||
except KeyboardInterrupt: | ||
exiting = 1 | ||
# as cleanup can take many seconds, trap Ctrl-C: | ||
signal.signal(signal.SIGINT, signal_ignore) | ||
if args.duration and seconds >= args.duration: | ||
exiting = 1 | ||
|
||
print() | ||
if args.timestamp: | ||
print("%-8s\n" % strftime("%H:%M:%S"), end="") | ||
|
||
dist.print_log2_hist(label) | ||
dist.clear() | ||
start.clear() | ||
|
||
if exiting: | ||
print("Detaching...") | ||
exit() |
Oops, something went wrong.