是否可以使用 eBPF 或 perf 来计算在单个跟踪函数中花费的时间?
Is it possible to use eBPF or perf to calculate time spent in individual traced functions?
目前,我可以告诉 trace-cmd
(一个 ftrace 前端)使用 ftrace 的函数图基础设施来跟踪指定的工作负载。使用一些跟踪数据处理工具,我可以查看调用函数的频率以及每个函数调用的相应总持续时间。示例输出可能如下所示,我在其中跟踪由我的工作负载生成的 ext4 函数调用:
# trace-cmd post-processing example output
# function name, frequency, total duration (us)
ext4_alloc_inode(),1,35.567
ext4_read_inode_bitmap(),1,12.076
ext4_init_io_end(),2,41.216
ext4_journal_check_start(),39,716.3
ext4_da_write_end(),10,102.661
ext4_da_get_block_prep(),9,257.46999999999997
ext4_block_write_begin(),2,88.069
ext4_bio_write_page(),1,33.016
我看到了eBPF
、systemtap
、perf
等可以产生的不可思议的flame graphs,这让我相信我应该能够使用 perf
或 eBPF
实现类似于我的 trace-cmd
输出的输出。但是,有一些障碍:
- 我的工作负载可以 运行 长达 15 分钟,如果我使用
perf
,这可能会生成大量日志。作为参考,您可以查看 example output 跟踪 bash 的时间要少得多。
- 我对
eBPF
不够熟悉,无法确定我是否可以实现与我的 trace-cmd
post 处理示例输出类似的 data/output。
对于那些比我更熟悉eBPF
或perf
的人,我想知道:
- 是否可以使用
eBPF
或 perf
来实现我的目标?
- 如果可以,为什么可能?
如果您觉得特别慷慨,请提供示例 code/commands 以帮助我实现我的目标,我们将不胜感激。
当然,可以使用 eBPF 来做到这一点。
实际上有一个工具可以做类似的事情 the bcc tools. funclatency 跟踪一组函数并显示它们的延迟直方图(每次调用在函数中花费的时间):
# ./funclatency do_sys_open
Tracing do_sys_open... Hit Ctrl-C to end.
^C
nsecs : 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 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 124 |**************** |
4096 -> 8191 : 291 |**************************************|
8192 -> 16383 : 36 |**** |
16384 -> 32767 : 16 |** |
32768 -> 65535 : 8 |* |
65536 -> 131071 : 0 | |
131072 -> 262143 : 0 | |
262144 -> 524287 : 0 | |
524288 -> 1048575 : 0 | |
1048576 -> 2097151 : 0 | |
2097152 -> 4194303 : 1 | |
Detaching...
从 funclatency 开始,很容易派生出一个工具来满足您的需求:
from __future__ import print_function
from bcc import BPF
from time import sleep, strftime
import argparse
parser = argparse.ArgumentParser(
description="Time functions and print time spent in each function",
formatter_class=argparse.RawDescriptionHelpFormatter)
parser.add_argument("-p", "--pid", type=int, help="trace this PID only")
parser.add_argument("pattern", help="search expression for functions")
args = parser.parse_args()
# define BPF program
bpf_text = """
#include <uapi/linux/ptrace.h>
struct stats_t {
u64 time;
u64 freq;
};
BPF_HASH(start, u32);
BPF_HASH(ipaddr, u32);
BPF_HASH(stats, u64, struct stats_t);
int trace_func_entry(struct pt_regs *ctx)
{
u64 pid_tgid = bpf_get_current_pid_tgid();
u32 pid = pid_tgid;
u64 ts = bpf_ktime_get_ns();
u64 ip = PT_REGS_IP(ctx);
ipaddr.update(&pid, &ip);
start.update(&pid, &ts);
return 0;
}
int trace_func_return(struct pt_regs *ctx)
{
u64 *tsp, delta;
u64 pid_tgid = bpf_get_current_pid_tgid();
u32 pid = 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);
// store as histogram
u64 ip, *ipp = ipaddr.lookup(&pid);
if (ipp) {
ip = *ipp;
struct stats_t *stat = stats.lookup(&ip);
if (stat) {
stat->time += delta;
stat->freq++;
} else {
struct stats_t s = {};
s.time = delta;
s.freq = 1;
stats.update(&ip, &s);
}
ipaddr.delete(&pid);
}
return 0;
}
"""
# load BPF program
b = BPF(text=bpf_text)
pattern = args.pattern.replace('*', '.*')
pattern = '^' + pattern + '$'
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))
while (1):
try:
sleep(99999999)
except KeyboardInterrupt:
break
print()
print("%-36s %8s %16s" % ("FUNC", "COUNT", "TIME (nsecs)"))
stats = b.get_table("stats")
for k, v in stats.items():
print("%-36s %8s %16s" % (BPF.sym(k.value, -1), v.freq, v.time))
此工具使用 BPF 直接在内核中计算每个函数调用的频率和总持续时间。聚合值仅在最后复制到用户空间,然后才显示它们。
输出:
# ./time-spent do_sys_*
Tracing 6 functions for "do_sys_*"... Hit Ctrl-C to end.
^C
FUNC COUNT TIME (nsecs)
do_sys_poll 6783 213928440379
do_sys_open 3127 43172656
do_sys_ftruncate.constprop.15 39 189623
此解决方案依赖 bcc 在内核中加载 BPF 程序,但也可以在 C 中完成所有操作。您可以找到 get started with bcc on the repository.
的教程
目前,我可以告诉 trace-cmd
(一个 ftrace 前端)使用 ftrace 的函数图基础设施来跟踪指定的工作负载。使用一些跟踪数据处理工具,我可以查看调用函数的频率以及每个函数调用的相应总持续时间。示例输出可能如下所示,我在其中跟踪由我的工作负载生成的 ext4 函数调用:
# trace-cmd post-processing example output
# function name, frequency, total duration (us)
ext4_alloc_inode(),1,35.567
ext4_read_inode_bitmap(),1,12.076
ext4_init_io_end(),2,41.216
ext4_journal_check_start(),39,716.3
ext4_da_write_end(),10,102.661
ext4_da_get_block_prep(),9,257.46999999999997
ext4_block_write_begin(),2,88.069
ext4_bio_write_page(),1,33.016
我看到了eBPF
、systemtap
、perf
等可以产生的不可思议的flame graphs,这让我相信我应该能够使用 perf
或 eBPF
实现类似于我的 trace-cmd
输出的输出。但是,有一些障碍:
- 我的工作负载可以 运行 长达 15 分钟,如果我使用
perf
,这可能会生成大量日志。作为参考,您可以查看 example output 跟踪 bash 的时间要少得多。 - 我对
eBPF
不够熟悉,无法确定我是否可以实现与我的trace-cmd
post 处理示例输出类似的 data/output。
对于那些比我更熟悉eBPF
或perf
的人,我想知道:
- 是否可以使用
eBPF
或perf
来实现我的目标? - 如果可以,为什么可能?
如果您觉得特别慷慨,请提供示例 code/commands 以帮助我实现我的目标,我们将不胜感激。
当然,可以使用 eBPF 来做到这一点。
实际上有一个工具可以做类似的事情 the bcc tools. funclatency 跟踪一组函数并显示它们的延迟直方图(每次调用在函数中花费的时间):
# ./funclatency do_sys_open
Tracing do_sys_open... Hit Ctrl-C to end.
^C
nsecs : 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 : 0 | |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 124 |**************** |
4096 -> 8191 : 291 |**************************************|
8192 -> 16383 : 36 |**** |
16384 -> 32767 : 16 |** |
32768 -> 65535 : 8 |* |
65536 -> 131071 : 0 | |
131072 -> 262143 : 0 | |
262144 -> 524287 : 0 | |
524288 -> 1048575 : 0 | |
1048576 -> 2097151 : 0 | |
2097152 -> 4194303 : 1 | |
Detaching...
从 funclatency 开始,很容易派生出一个工具来满足您的需求:
from __future__ import print_function
from bcc import BPF
from time import sleep, strftime
import argparse
parser = argparse.ArgumentParser(
description="Time functions and print time spent in each function",
formatter_class=argparse.RawDescriptionHelpFormatter)
parser.add_argument("-p", "--pid", type=int, help="trace this PID only")
parser.add_argument("pattern", help="search expression for functions")
args = parser.parse_args()
# define BPF program
bpf_text = """
#include <uapi/linux/ptrace.h>
struct stats_t {
u64 time;
u64 freq;
};
BPF_HASH(start, u32);
BPF_HASH(ipaddr, u32);
BPF_HASH(stats, u64, struct stats_t);
int trace_func_entry(struct pt_regs *ctx)
{
u64 pid_tgid = bpf_get_current_pid_tgid();
u32 pid = pid_tgid;
u64 ts = bpf_ktime_get_ns();
u64 ip = PT_REGS_IP(ctx);
ipaddr.update(&pid, &ip);
start.update(&pid, &ts);
return 0;
}
int trace_func_return(struct pt_regs *ctx)
{
u64 *tsp, delta;
u64 pid_tgid = bpf_get_current_pid_tgid();
u32 pid = 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);
// store as histogram
u64 ip, *ipp = ipaddr.lookup(&pid);
if (ipp) {
ip = *ipp;
struct stats_t *stat = stats.lookup(&ip);
if (stat) {
stat->time += delta;
stat->freq++;
} else {
struct stats_t s = {};
s.time = delta;
s.freq = 1;
stats.update(&ip, &s);
}
ipaddr.delete(&pid);
}
return 0;
}
"""
# load BPF program
b = BPF(text=bpf_text)
pattern = args.pattern.replace('*', '.*')
pattern = '^' + pattern + '$'
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))
while (1):
try:
sleep(99999999)
except KeyboardInterrupt:
break
print()
print("%-36s %8s %16s" % ("FUNC", "COUNT", "TIME (nsecs)"))
stats = b.get_table("stats")
for k, v in stats.items():
print("%-36s %8s %16s" % (BPF.sym(k.value, -1), v.freq, v.time))
此工具使用 BPF 直接在内核中计算每个函数调用的频率和总持续时间。聚合值仅在最后复制到用户空间,然后才显示它们。 输出:
# ./time-spent do_sys_*
Tracing 6 functions for "do_sys_*"... Hit Ctrl-C to end.
^C
FUNC COUNT TIME (nsecs)
do_sys_poll 6783 213928440379
do_sys_open 3127 43172656
do_sys_ftruncate.constprop.15 39 189623
此解决方案依赖 bcc 在内核中加载 BPF 程序,但也可以在 C 中完成所有操作。您可以找到 get started with bcc on the repository.
的教程