eBPFLAB 专注eBPF创新技术 | 可观测性 ftrace

介绍

ftrace是Function Tracer的意思，最开始主要用于记录内核函数运行轨迹；随着功能的逐渐增加，演变成一个跟踪框架。

ftrace的运行不需要额外的程序，它内置在内核中，通过debugfs文件系统和用户交互。当然也有一些用户态程序方便用户交互，比如trace-cmd、kernelshark。

工作原理

ftrace机制的执行，依赖于gcc的-pg编译选项，-pg选项在每个函数执行前插入mcount（和体系架构有关，不同架构名字有所差异）。在未启用追踪功能的时候，插入的指令为NOP，不做任何事情，启用追踪功能之后，NOP指令会被替换成ftrace_caller。

mcout是一个trampoline跳床，它返回函数的返回值，提供了一种在原流程中执行桩函数的机制。

ftrace_caller 工作如下图所示

使用

ftrace的使用比较简单，与ftrace交互的API位于debufs文件系统中，通常在/sys/kernel/debug/目录下。

因为ftrace是直接内置于内核中的的，所以使用它需要配置内核支持。

通常开启如下几项配置

CONFIG_FUNCTION_TRACER
CONFIG_FUNCTION_GRAPH_TRACER
CONFIG_DYNAMIC_FTRACE

其分为静态和动态trace，常使用动态trace。

查看支持哪些tracer

# cat /sys/kernel/debug/tracing/available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

设置使用那个tracer

# echo wakeup > /sys/kernel/debug/tracing/current_tracer

查看当前使用的tracer

# cat /sys/kernel/debug/tracing/current_tracer
wakeup

启用/停用追踪

echo 1 > /sys/kernel/debug/tracing/tracing_on
echo 0 > /sys/kernel/debug/tracing/tracing_on

查看追踪的结果 (从文件中)

# cat /sys/kernel/debug/tracing/trace |more
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 5.4.0-42-generic
# --------------------------------------------------------------------
# latency: 8450 us, #16610/16610, CPU#3 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: systemd-journal-575 (uid:0 nice:-1 policy:0 rt_prio:0)
#    -----------------
#
#                  _------=> CPU#
#                 / _-----=> irqs-off
#                | / _----=> need-resched
#                || / _---=> hardirq/softirq
#                ||| / _--=> preempt-depth
#                |||| /     delay
#  cmd     pid   ||||| time  |   caller
#     \   /      |||||  \    |   /
 systemd-1       3d...    0us+:      1:120:R   + [003]   575:119:R systemd-journal
 systemd-1       3d...   14us : <stack trace>
 => __trace_stack
 => probe_wakeup
 => ttwu_do_wakeup
 => ttwu_do_activate
 => try_to_wake_up
 => default_wake_function
 => autoremove_wake_function
 => __wake_up_common
 => __wake_up_common_lock
 => __wake_up
 => ep_poll_callback
....

查看追踪结果，直接输出到命令行，与上面输出结果一样。

# cat /sys/kernel/debug/tracing/trace_pipe

查看支持的动态追踪点

# cat /sys/kernel/debug/tracing/available_filter_functions |more
trace_initcall_finish_cb
initcall_blacklisted
do_one_initcall
do_one_initcall
trace_initcall_start_cb
run_init_process
try_to_run_init_process
match_dev_by_label
match_dev_by_uuid
rootfs_init_fs_context

查看当前设置的动态追踪点,默认所有的都支持。

# cat /sys/kernel/debug/tracing/set_ftrace_filter
#### all functions enabled ####

监控某些函数

# echo xxx某函数 > /sys/kernel/debug/tracing/set_ftrace_filter

设置tracer 查看监控

# cat /sys/kernel/debug/tracing/trace

实验

ping 127.0.0.1 查看trace

设置动态追踪函数 icmp_rcv 、__sys_socket

# echo icmp_rcv > /sys/kernel/debug/tracing/set_ftrace_filter
# cat set_ftrace_filter
icmp_rcv

设置tracer

# echo function_graph > /sys/kernel/debug/tracing/current_tracer
# cat current_tracer
function_graph

ping 127.0.0.1

# ping 127.0.0.1
PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.035 ms
64 bytes from 127.0.0.1: icmp_seq=2 ttl=64 time=0.116 ms
64 bytes from 127.0.0.1: icmp_seq=3 ttl=64 time=0.113 ms
^C
--- 127.0.0.1 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2031ms
rtt min/avg/max/mdev = 0.035/0.088/0.116/0.037 ms

查看追踪情况

# cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
   2)   9.289 us    |  icmp_rcv();
   2)   1.422 us    |  icmp_rcv();
   2) + 26.285 us   |  icmp_rcv();
   2)   6.820 us    |  icmp_rcv();
   2) + 25.768 us   |  icmp_rcv();
   2)   6.255 us    |  icmp_rcv();

参考

https://en.wikipedia.org/wiki/Ftrace https://www.cnblogs.com/arnoldlu/p/7211249.html https://docs.kernel.org/trace/ftrace.html

https://lwn.net/Articles/322666

欢迎大家转发分享。未经授权，严禁任何复制、转载、摘编或以其它方式进行使用，转载须注明来自eBPFLAB并附上本文链接。如果有侵犯到您权益的地方，请及时联系我删除。