目录
概述
动态追踪技术,通过探针机制,来采集内核或者应用程序的运行信息,从而可以不用修改内核和应用程序的代码,
就获得丰富的信息,帮你分析、定位想要排查的问题。
以往,在排查和调试性能问题时,我们往往需要先为应用程序设置一系列的断点(比如使用 GDB),
然后以手动或者脚本(比如 GDB 的 Python 扩展)的方式,在这些断点处分析应用程序的状态。
或者,增加一系列的日志,从日志中寻找线索。
不过,断点往往会中断应用的正常运行;而增加新的日志,往往需要重新编译和部署。这些方法虽然在今天依然广泛使用,
但在排查复杂的性能问题时,往往耗时耗力,更会对应用的正常运行造成巨大影响。
此外,这类方式还有大量的性能问题。比如,出现的概率小,只有线上环境才能碰到。这种难以复现的问题,亦是一个巨大挑战。
而动态追踪技术的出现,就为这些问题提供了完美的方案:它既不需要停止服务,也不需要修改应用程序的代码;
所有一切还按照原来的方式正常运行时,就可以帮你分析出问题的根源。
同时,相比以往的进程级跟踪方法(比如 ptrace),动态追踪往往只会带来很小的性能损耗(通常在 5% 或者更少)。
动态追踪
说到动态追踪(Dynamic Tracing),就不得不提源于 Solaris 系统的 DTrace。DTrace 是动态追踪技术的鼻祖,
它提供了一个通用的观测框架,并可以使用 D 语言进行自由扩展。
DTrace 的工作原理如下图所示。它的运行常驻在内核中,用户可以通过 dtrace 命令,把 D 语言编写的追踪脚本,
提交到内核中的运行时来执行。DTrace 可以跟踪用户态和内核态的所有事件,并通过一些列的优化措施,保证最小的性能开销。
虽然直到今天,DTrace 本身依然无法在 Linux 中运行,但它同样对 Linux 动态追踪产生了巨大的影响。
很多工程师都尝试过把 DTrace 移植到 Linux 中,这其中,最著名的就是 RedHat 主推的 SystemTap。
同 DTrace 一样,SystemTap 也定义了一种类似的脚本语言,方便用户根据需要自由扩展。不过,不同于 DTrace,
SystemTap 并没有常驻内核的运行时,它需要先把脚本编译为内核模块,然后再插入到内核中执行。
这也导致 SystemTap 启动比较缓慢,并且依赖于完整的调试符号表。
总的来说,为了追踪内核或用户空间的事件,
Dtrace 和 SystemTap 都会把用户传入的追踪处理函数(一般称为 Action),
关联到被称为探针的检测点上。这些探针,实际上也就是各种动态追踪技术所依赖的事件源。
动态追踪的事件源
根据事件类型的不同,动态追踪所使用的事件源,可以分为
静态探针、动态探针以及硬件事件等三类。它们的关系如下图所示:
硬件事件通常由性能监控计数器 PMC(Performance Monitoring Counter)产生,包括了各种硬件的性能情况,
比如 CPU 的缓存、指令周期、分支预测等等。
静态探针,是指事先在代码中定义好,并编译到应用程序或者内核中的探针。这些探针只有在开启探测功能时,
才会被执行到;未开启时并不会执行。常见的静态探针包括内核中的跟踪点(tracepoints)和
USDT(Userland Statically Defined Tracing)探针。
- 跟踪点(tracepoints),实际上就是在源码中插入的一些带有控制条件的探测点,这些探测点允许事后再添加处理函数。比如在内核中,最常见的静态跟踪方法就是 printk,即输出日志。Linux 内核定义了大量的跟踪点,可以通过内核编译选项,来开启或者关闭。
- USDT 探针,全称是用户级静态定义跟踪,需要在源码中插入 DTRACE_PROBE() 代码,并编译到应用程序中。不过,也有很多应用程序内置了 USDT 探针,比如 MySQL、PostgreSQL 等。
动态探针,则是指没有事先在代码中定义,但却可以在运行时动态添加的探针,比如函数的调用和返回等。
动态探针支持按需在内核或者应用程序中添加探测点,具有更高的灵活性。常见的动态探针有两种,
即用于内核态的 kprobes 和用于用户态的 uprobes。
- kprobes 用来跟踪内核态的函数,包括用于函数调用的 kprobe 和用于函数返回的 kretprobe。
- uprobes 用来跟踪用户态的函数,包括用于函数调用的 uprobe 和用于函数返回的 uretprobe。
注意,kprobes 需要内核编译时开启 CONFIG_KPROBE_EVENTS;而 uprobes 则需要内核编译时开启 CONFIG_UPROBE_EVENTS。
动态追踪机制
在这些探针的基础上,Linux 也提供了一系列的动态追踪机制,比如 ftrace、perf、eBPF 等。
- ftrace 最早用于函数跟踪,后来又扩展支持了各种事件跟踪功能。ftrace 的使用接口跟我们之前提到的 procfs 类似,它通过 debugfs(4.1 以后也支持 tracefs),以普通文件的形式,向用户空间提供访问接口。不需要额外的工具,你就可以通过挂载点(通常为 /sys/kernel/debug/tracing 目录)内的文件读写,来跟 ftrace 交互,跟踪内核或者应用程序的运行事件。
- perf 这实际上只是一种最简单的静态跟踪机制。可以通过 perf ,来自定义动态事件(perf probe),只关注真正感兴趣的事件。
- eBPF 则在 BPF(Berkeley Packet Filter)的基础上扩展而来,不仅支持事件跟踪机制,还可以通过自定义的 BPF 代码(使用 C 语言)来自由扩展。所以,eBPF 实际上就是常驻于内核的运行时,可以说就是 Linux 版的 DTrace。
- 除此之外,还有很多内核外的工具,也提供了丰富的动态追踪功能。最常见的是 SystemTap,BCC(BPF Compiler Collection),以及常用于容器性能分析的 sysdig 等。
ftrace
通过debugfs(或者tracefs),为用户提供接口,所以使用ftrce,是从切换到debugfs的挂载点开始
cd /sys/kernel/debug/tracing
ls
available_events dyn_ftrace_total_info instances printk_formats set_ftrace_notrace stack_trace_filter trace_stat uprobe_profile
available_filter_functions enabled_functions kprobe_events README set_ftrace_pid trace tracing_cpumask
available_tracers events kprobe_profile saved_cmdlines set_graph_function trace_clock tracing_max_latency
buffer_size_kb free_buffer max_graph_depth saved_cmdlines_size snapshot trace_marker tracing_on
buffer_total_size_kb function_profile_enabled options set_event stack_max_size trace_options tracing_thresh
current_tracer hwlat_detector per_cpu set_ftrace_filter stack_trace trace_pipe uprobe_events
如果这个目录不存在,说明系统还没挂在debugfs,可以执行下面命令来挂载
mount -t debugfs nodev /sys/kernel/debug
ftrace提供了多个跟踪器,用户跟踪不同类型的类型,如函数调用,中断关闭,进程调度等
具体支持的跟踪器取决于系统配置
#查看所有支持的跟踪器
cat available_tracers
blk kmemtrace function_graph wakeup_rt wakeup function sysprof sched_switch initcall nop
function表示跟踪函数的执行,function_graph则是跟踪函数的调用关系,也就是生成直观的调用关系图
使用ftrace前,还需要确认跟踪目标,包括内核函数和内核事件
- 函数就是内核中的函数名
- 事件是内核源码中预先定义的跟踪点
#查询支持的函数和事件
cat available_filter_functions
cat available_events
以跟踪ls为例,这个命令会调用打开目录文件,open在内核中对应的函数为do_sys_open
#第一步,设置跟踪函数
echo do_sys_open > set_graph_function
#第二步,配置跟踪选项,开启函数调用跟踪,并跟踪调用进程
echo function_graph > current_trace
echo funcgraph-proc > trace_options
#第三步,开启跟踪
echo 1 > tracing_on
#第四步,执行ls命令后再关闭跟踪
ls
echo 0 > tracing_on
#第五步,查看跟踪结果
cat trace | head -n 100
# tracer: function_graph
#
# TIME CPU TASK/PID DURATION FUNCTION CALLS
# | | | | | | | | | |
2) <...>-14725 | 0.825 us | kmem_cache_free();
2) <...>-14725 | 1.675 us | }
2) <...>-14725 | | file_free_rcu() {
2) <...>-14725 | 0.420 us | kmem_cache_free();
2) <...>-14725 | 1.187 us | }
2) <...>-14725 | | file_free_rcu() {
2) <...>-14725 | 0.385 us | kmem_cache_free();
2) <...>-14725 | 1.140 us | }
2) <...>-14725 | | file_free_rcu() {
2) <...>-14725 | 0.395 us | kmem_cache_free();
2) <...>-14725 | 1.160 us | }
2) <...>-14725 | | file_free_rcu() {
2) <...>-14725 | 0.387 us | kmem_cache_free();
2) <...>-14725 | 1.133 us | }
2) <...>-14725 | | file_free_rcu() {
2) <...>-14725 | 0.385 us | kmem_cache_free();
2) <...>-14725 | 1.185 us | }
2) <...>-14725 | 0.388 us | raise_softirq();
在最后得到的输出中
- 第一列表示运行的CPU
- 第二列是任务名称和进程PID
- 第三列是函数执行延迟
- 最后一列是函数调用关系图
通过trace-cmd来简化ftrace的步骤
trace-cmd record -p function_graph -g do_sys_open -O funcgraph-proc ls
trace-cmd report
cpus=1
trace-cmd-6269 [000] 60101.216947: funcgraph_entry: | do_sys_open() {
trace-cmd-6269 [000] 60101.216950: funcgraph_entry: | getname() {
trace-cmd-6269 [000] 60101.216950: funcgraph_entry: | getname_flags() {
trace-cmd-6269 [000] 60101.216950: funcgraph_entry: | kmem_cache_alloc() {
trace-cmd-6269 [000] 60101.216951: funcgraph_entry: 0.051 us | _cond_resched();
trace-cmd-6269 [000] 60101.216952: funcgraph_exit: 1.110 us | }
trace-cmd-6269 [000] 60101.216952: funcgraph_entry: | do_async_page_fault() {
trace-cmd-6269 [000] 60101.216952: funcgraph_entry: | trace_do_page_fault() {
trace-cmd-6269 [000] 60101.216952: funcgraph_entry: | __do_page_fault() {
trace-cmd-6269 [000] 60101.216953: funcgraph_entry: 0.047 us | down_read_trylock();
trace-cmd-6269 [000] 60101.216953: funcgraph_entry: 0.043 us | _cond_resched();
trace-cmd-6269 [000] 60101.216953: funcgraph_entry: 0.101 us | find_vma();
trace-cmd-6269 [000] 60101.216954: funcgraph_entry: | handle_mm_fault() {
trace-cmd-6269 [000] 60101.216954: funcgraph_entry: 0.120 us | __mem_cgroup_count_vm_event();
trace-cmd-6269 [000] 60101.216954: funcgraph_entry: | handle_pte_fault() {
trace-cmd-6269 [000] 60101.216955: funcgraph_entry: | do_read_fault.isra.61() {
trace-cmd-6269 [000] 60101.216955: funcgraph_entry: | __do_fault.isra.59() {
trace-cmd-6269 [000] 60101.216955: funcgraph_entry: | ext4_filemap_fault() {
trace-cmd-6269 [000] 60101.216955: funcgraph_entry: | down_read() {
trace-cmd-6269 [000] 60101.216956: funcgraph_entry: 0.047 us | _cond_resched();
trace-cmd-6269 [000] 60101.216956: funcgraph_exit: 0.921 us | }
trace-cmd-6269 [000] 60101.216957: funcgraph_entry: | filemap_fault() {
trace-cmd-6269 [000] 60101.216957: funcgraph_entry: 0.174 us | __find_get_page();
trace-cmd-6269 [000] 60101.216957: funcgraph_entry: 0.045 us | _cond_resched();
trace-cmd-6269 [000] 60101.216958: funcgraph_exit: 0.886 us | }
trace-cmd-6269 [000] 60101.216958: funcgraph_entry: 0.044 us | up_read();
trace-cmd-6269 [000] 60101.216958: funcgraph_exit: 2.757 us | }
trace-cmd-6269 [000] 60101.216958: funcgraph_exit: 3.224 us | }
trace-cmd-6269 [000] 60101.216958: funcgraph_entry: 0.040 us | _raw_qspin_lock();
参考