- 原文作者：DavidDi
- 原文链接：https://www.ebpf.top/post/system_debug_stack/
- 版权声明：本作品采用知识共享署名-非商业性使用-禁止演绎 4.0 国际许可协议进行许可，非商业转载请注明出处（作者，原文链接），商业转载请联系作者获得授权。
目录
1. 系统的线程栈跟踪（内核）
在某些特殊场景中，我们可能会遇到偶发系统内核 CPU 抖动，这时候我们可能需要知晓动时刻内核中的所有运行任务的一个快照，这种场景下 sysrq 可以完全满足我们的需求。
如果只是需要分析系统的热点路径，perf 会是一个比较好的选择。
1.1 sysrq 是什么？
sysrq 代表的是 Magic System Request Key。开启了该功能以后，只要内核没有挂掉，它就会响应你要求的任何操作。但是这需要内核支持 (CONFIG_MAGIC_SYSRQ 编译支持)。向 /proc/sys/kernel/sysrq 中写入 0 是关闭 sysrq 功能，写入 1 是开启，其他选项请参考 sysrq.txt。需要注意的是，/proc/sys/kernel/sysrq 中的值只影响键盘的操作。
那么怎么使用 sysrq 键呢？
在 x86 平台上，组合键 " + SysRq +" 组成 sysrq 键以完成各种功能，常见的如下：
'b' —— 将会立即重启系统，并且不会管你有没有数据没有写回磁盘，也不卸载磁盘，而是完完全全的立即关机
'o' —— 将会关机
's' —— 将会同步所有以挂在的文件系统
'u' —— 将会重新将所有的文件系统挂在为只读属性
/proc/sysrq-trigger 文件就是为了在后台系统实现 sysrq 功能，写入到该文件的字符就代表了上述键值对应的功能，比如：
echo "b" > /proc/sysrq-trigger # 立即关闭计算机（shuts off the system）
1.2 sysrq 打印系统线程信息
字母 t 代表导出线程状态信息，输出到系统内核日志文件中，如下：
echo "t" > /proc/sysrq-trigger
输入上述指令的终端会 hang 住，通常我们需要打开一个新的终端通过 dmesg -T > /tmp/dmesg.log 查看结果，一般打印的栈会比较多，所以一般需要重定向到文件中查看。
[Tue Jul 20 15:59:45 2021] SysRq :
[Tue Jul 20 15:59:45 2021] Show State
[Tue Jul 20 15:59:45 2021] task PC stack pid father
[Tue Jul 20 15:59:45 2021] systemd S ffff957362378000 0 1 0 0x10000000
[Tue Jul 20 15:59:45 2021] Call Trace:
[Tue Jul 20 15:59:45 2021] [<ffffffff8b387dd9>] schedule+0x29/0x70
[Tue Jul 20 15:59:45 2021] [<ffffffff8b38703d>] schedule_hrtimeout_range_clock+0x12d/0x150
[Tue Jul 20 15:59:45 2021] [<ffffffff8ae9cec9>] ? ep_scan_ready_list.isra.7+0x1b9/0x1f0
[Tue Jul 20 15:59:45 2021] [<ffffffff8b387073>] schedule_hrtimeout_range+0x13/0x20
[Tue Jul 20 15:59:45 2021] [<ffffffff8ae9d15e>] ep_poll+0x23e/0x360
[Tue Jul 20 15:59:45 2021] [<ffffffffc05de92f>] ? record_event_consumer+0x1f/0x30 [falco]
[Tue Jul 20 15:59:45 2021] [<ffffffff8acdb130>] ? wake_up_state+0x20/0x20
[Tue Jul 20 15:59:45 2021] [<ffffffff8ae9e63d>] SyS_epoll_wait+0xed/0x120
[Tue Jul 20 15:59:45 2021] [<ffffffff8b395226>] tracesys+0xa6/0xcc
....
# 在所有线程堆栈打印后，还会输出调度器和各个 CPU 上运行的调度信息和任务详情。
[Tue Jul 20 15:59:49 2021] Sched Debug Version: v0.11, 3.10.0-1160.15.2.el7.x86_64 #1
[Tue Jul 20 15:59:49 2021] ktime : 4398082790.731800
[Tue Jul 20 15:59:49 2021] sched_clk : 4397970354.112112
[Tue Jul 20 15:59:49 2021] cpu_clk : 4397970354.112331
[Tue Jul 20 15:59:49 2021] jiffies : 8692750091
[Tue Jul 20 15:59:49 2021] sched_clock_stable() : 1
[Tue Jul 20 15:59:49 2021] sysctl_sched
[Tue Jul 20 15:59:49 2021] .sysctl_sched_latency : 24.000000
[Tue Jul 20 15:59:49 2021] .sysctl_sched_min_granularity : 10.000000
[Tue Jul 20 15:59:49 2021] .sysctl_sched_wakeup_granularity : 15.000000
[Tue Jul 20 15:59:49 2021] .sysctl_sched_child_runs_first : 0
[Tue Jul 20 15:59:49 2021] .sysctl_sched_features : 40571
[Tue Jul 20 15:59:49 2021] .sysctl_sched_tunable_scaling : 1 (logaritmic)
[Tue Jul 20 15:59:49 2021] cpu#0, 2499.984 MHz
[Tue Jul 20 15:59:49 2021] .nr_running : 0
[Tue Jul 20 15:59:49 2021] .load : 0
[Tue Jul 20 15:59:49 2021] .nr_switches : 991867687
[Tue Jul 20 15:59:49 2021] .nr_load_updates : 492151717
[Tue Jul 20 15:59:49 2021] .nr_uninterruptible : 88050
[Tue Jul 20 15:59:49 2021] .next_balance : 8692.750103
[Tue Jul 20 15:59:49 2021] .curr->pid : 0
[Tue Jul 20 15:59:49 2021] .clock : 4397970370.991376
[Tue Jul 20 15:59:49 2021] .cpu_load[0] : 0
[Tue Jul 20 15:59:49 2021] .cpu_load[1] : 0
[Tue Jul 20 15:59:49 2021] .cpu_load[2] : 0
[Tue Jul 20 15:59:49 2021] .cpu_load[3] : 0
[Tue Jul 20 15:59:49 2021] .cpu_load[4] : 0
[Tue Jul 20 15:59:49 2021] .avg_idle : 922036
[Tue Jul 20 15:59:49 2021] .max_idle_balance_cost : 500000
[Tue Jul 20 15:59:49 2021] cfs_rq[0]:/
[Tue Jul 20 15:59:49 2021] .exec_clock : 0.000000
[Tue Jul 20 15:59:49 2021] .MIN_vruntime : 0.000001
[Tue Jul 20 15:59:49 2021] .min_vruntime : 3581919.011171
[Tue Jul 20 15:59:49 2021] .max_vruntime : 0.000001
[Tue Jul 20 15:59:49 2021] .spread : 0.000000
[Tue Jul 20 15:59:49 2021] .spread0 : 0.000000
[Tue Jul 20 15:59:49 2021] .nr_spread_over : 0
[Tue Jul 20 15:59:49 2021] .nr_running : 0
[Tue Jul 20 15:59:49 2021] .load : 0
[Tue Jul 20 15:59:49 2021] .runnable_load_avg : 0
[Tue Jul 20 15:59:49 2021] .blocked_load_avg : 41
[Tue Jul 20 15:59:49 2021] .tg_load_avg : 0
[Tue Jul 20 15:59:49 2021] .tg_load_contrib : 0
[Tue Jul 20 15:59:49 2021] .tg_runnable_contrib : 0
[Tue Jul 20 15:59:49 2021] .tg->runnable_avg : 0
[Tue Jul 20 15:59:49 2021] .tg->cfs_bandwidth.timer_active: 0
[Tue Jul 20 15:59:49 2021] .throttled : 0
[Tue Jul 20 15:59:49 2021] .throttle_count : 0
[Tue Jul 20 15:59:49 2021] .avg->runnable_avg_sum : 459
[Tue Jul 20 15:59:49 2021] .avg->runnable_avg_period : 46637
[Tue Jul 20 15:59:49 2021] rt_rq[0]:/assist
[Tue Jul 20 15:59:49 2021] .rt_nr_running : 0
[Tue Jul 20 15:59:49 2021] .rt_throttled : 0
[Tue Jul 20 15:59:49 2021] .rt_time : 0.000000
[Tue Jul 20 15:59:49 2021] .rt_runtime : 0.000000
[Tue Jul 20 15:59:49 2021] rt_rq[0]:/aegis
[Tue Jul 20 15:59:49 2021] .rt_nr_running : 0
[Tue Jul 20 15:59:49 2021] .rt_throttled : 0
[Tue Jul 20 15:59:49 2021] .rt_time : 0.000000
[Tue Jul 20 15:59:49 2021] .rt_runtime : 0.000000
[Tue Jul 20 15:59:49 2021] rt_rq[0]:/
[Tue Jul 20 15:59:49 2021] .rt_nr_running : 0
[Tue Jul 20 15:59:49 2021] .rt_throttled : 0
[Tue Jul 20 15:59:49 2021] .rt_time : 0.000000
[Tue Jul 20 15:59:49 2021] .rt_runtime : 950.000000
[Tue Jul 20 15:59:49 2021] runnable tasks:
[Tue Jul 20 15:59:49 2021] task PID tree-key switches prio wait-time sum-exec sum-sleep
[Tue Jul 20 15:59:49 2021] ---------------------------------------------------------------------------------
[Tue Jul 20 15:59:49 2021] systemd 1 3581906.537071519536 120 0.000000 95337.326576 0.000000 0 /
....
如果抖动是偶发的抖动，我们通过命令来执行并不一定有效，这时候就可以使用一些自动化脚本进行触发，以下样例是排查 sys CPU 抖动问题的脚本可供参考。
该脚本会检测 sys 利用率高于 15% 同时 usr 较低的情况，也就是说检测 CPU 是否在内核里花费了太多时间。如果出现这种情况，就会运行 sysrq 来保存当前任务快照。
#!/bin/sh
while [ 1 ]; do
top -bn2 | grep "Cpu(s)" | tail -1 | awk '{
# $2 is usr, $4 is sys.
if ($2 < 30.0 && $4 > 15.0) {
# save the current usr and sys into a tmp file
while ("date" | getline date) {
split(date, str, " ");
prefix=sprintf("%s_%s_%s_%s", str[2],str[3], str[4], str[5]);
}
sys_usr_file=sprintf("/tmp/%s_info.highsys", prefix);
print $2 > sys_usr_file;
print $4 >> sys_usr_file;
# run sysrq
system("echo t > /proc/sysrq-trigger");
}
}'
sleep 1m
done
脚本来自于 《Linux内核技术实战课》- 《18 案例篇 | 业务是否需要使用透明大页：水可载舟，亦可覆舟？》。
1.3 底层实现原理 （可跳过）
sysrq-trigger 对应的触发的实现在文件 drivers/tty/sysrq.c 中，sysrq_key_table 表定义了所有支持的 key，这里我们可以看到字母 t 对应的处理处理结构为 sysrq_showstate_op。
static const struct sysrq_key_op *sysrq_key_table[62] = {
&sysrq_loglevel_op, /* 0 */
// ...
&sysrq_showstate_op, /* t */
// ...
}
sysrq_handle_showstate 函数为最终功能实现函数，分别调用了 show_state() 和 show_workqueue_state() 两个函数，这里我们重点跟踪 show_state。
static const struct sysrq_key_op sysrq_showstate_op = {
.handler = sysrq_handle_showstate,
.help_msg = "show-task-states(t)",
.action_msg = "Show State",
.enable_mask = SYSRQ_ENABLE_DUMP,
};
static void sysrq_handle_showstate(int key)
{
show_state(); // 打印系统中所有的进程和线程状态
show_workqueue_state(); // 用于打印工作队列中的栈
}
show_state 的函数定义在 include/linux/sched/debug.h 文件中，直接传参调用了 show_state_filter，参数传递为 0。
static inline void show_state(void)
{
show_state_filter(0);
}
show_state_filter 函数定义在 kernel/sched/core.c 文件中，完整实现代码如下：
void show_state_filter(unsigned int state_filter)
{
struct task_struct *g, *p;
rcu_read_lock();
for_each_process_thread(g, p) {
/*
* reset the NMI-timeout, listing all files on a slow
* console might take a lot of time:
* Also, reset softlockup watchdogs on all CPUs, because
* another CPU might be blocked waiting for us to process
* an IPI.
*/
touch_nmi_watchdog();
touch_all_softlockup_watchdogs();
if (state_filter_match(state_filter, p))
sched_show_task(p);
}
#ifdef CONFIG_SCHED_DEBUG
if (!state_filter)
sysrq_sched_debug_show();
#endif
rcu_read_unlock();
/*
* Only show locks if all tasks are dumped:
*/
if (!state_filter)
debug_show_all_locks();
}
宏 for_each_process_thread 实现了所有进程和线程的遍历，函数 sched_show_task 实现了 task_struct 结构具体信息打印。sched_show_task 整体代码实现如下：
void sched_show_task(struct task_struct *p)
{
unsigned long free = 0;
int ppid;
if (!try_get_task_stack(p))
return;
pr_info("task:%-15.15s state:%c", p->comm, task_state_to_char(p));
if (task_is_running(p))
pr_cont(" running task ");
ppid = 0;
pr_cont(" stack:%5lu pid:%5d ppid:%6d flags:0x%08lx\n",
free, task_pid_nr(p), ppid,
(unsigned long)task_thread_info(p)->flags);
print_worker_info(KERN_INFO, p);
print_stop_info(KERN_INFO, p);
show_stack(p, NULL, KERN_INFO);
put_task_stack(p);
}
EXPORT_SYMBOL_GPL(sched_show_task);
2. 进程线程/协程栈跟踪
对于进程级别的跟踪大体分成两类，一类是直接使用线程库创建的，可以直接使用 pstack 工具进行参看；还有一类是 Golang 语言中的 Goroutine 的栈跟踪，由于使用户空间实现的栈跟踪，需要语言层面的支持。
2.1 使用 pstack 输出线程栈
gdb 工具集中的 pstack 命令可以用于打印进程中线程栈跟踪。如果发现一个程序处于假死或者死循环的状态， 多次运行 pstack 工具可以比较容易定位到程序的可疑点。如果程序处于死循环状态，使用 perf top 的方式效果更好，可以实时发现热点代码。
pstack 工具需要安装 gdb 工具包。在 CentOS 系统中：
# yum install gdb -y
# pstack pid
# ls -hl /bin/pstack
lrwxrwxrwx 1 root root 6 Dec 2 2020 /bin/pstack -> gstack # 底层为 gstack
通过以上命令可以看出 pstack 底层指向 gstack， 使用的方式比较简单，运行 pstack pid 即可。
# pstack 25735
Thread 3 (Thread 0x7f043a507700 (LWP 25771)):
#0 0x00007f043d42587d in pause () from /lib64/libc.so.6
#1 0x00007f043d456154 in ualarm () from /lib64/libc.so.6
#2 0x00007f0440e8b320 in aqs::CThreadUtil::SetPthreadId() () from /usr/local/aegis/aegis_client/aegis_10_97/libaqsUtil.so.1
#3 0x00007f0440e8bc1a in aqs::CThreadUtil::ThreadFunc(void*) () from /usr/local/aegis/aegis_client/aegis_10_97/libaqsUtil.so.1
#4 0x00007f043f19eea5 in start_thread () from /lib64/libpthread.so.0
#5 0x00007f043d45e98d in ?? () from /lib64/libc.so.6
#6 0x0000000000000000 in ?? ()
Thread 2 (Thread 0x7f043a406700 (LWP 25772)):
#0 0x00007f043d42587d in pause () from /lib64/libc.so.6
#1 0x00007f043d456154 in ualarm () from /lib64/libc.so.6
#2 0x0000000000000009 in ?? ()
#3 0x00007f043a406700 in ?? ()
#4 0x00000000cd3f3680 in ?? ()
#5 0x0000000000000000 in ?? ()
Thread 1 (Thread 0x7f04412cc780 (LWP 25735)):
#0 0x00007f043d42587d in pause () from /lib64/libc.so.6
#1 0x00007f043d456154 in ualarm () from /lib64/libc.so.6
#2 0x0000000000000000 in ?? ()
gstack 的实现为 shell 脚本，底层使用 gdb + backtrace 进行实际的工作。脚本底层对于不同内核的 bt 命令上进行对应的处理。
# cat /bin/gstack
#!/bin/sh
if test $# -ne 1; then
echo "Usage: `basename $0 .sh` <process-id>" 1>&2
exit 1
fi
if test ! -r /proc/$1; then
echo "Process $1 not found." 1>&2
exit 1
fi
# GDB doesn't allow "thread apply all bt" when the process isn't
# threaded; need to peek at the process to determine if that or the
# simpler "bt" should be used.
backtrace="bt" # 默认为 bt
if test -d /proc/$1/task ; then
# Newer kernel; has a task/ directory.
if test `/bin/ls /proc/$1/task | /usr/bin/wc -l` -gt 1 2>/dev/null ; then
backtrace="thread apply all bt"
fi
elif test -f /proc/$1/maps ; then
# Older kernel; go by it loading libpthread.
if /bin/grep -e libpthread /proc/$1/maps > /dev/null 2>&1 ; then
backtrace="thread apply all bt"
fi
fi
GDB=${GDB:-/usr/bin/gdb}
# Run GDB, strip out unwanted noise.
# --readnever is no longer used since .gdb_index is now in use.
$GDB --quiet -nx $GDBARGS /proc/$1/exe $1 <<EOF 2>&1 |
set width 0
set height 0
set pagination no
$backtrace
EOF
/bin/sed -n \
-e 's/^\((gdb) \)*//' \
-e '/^#/p' \
-e '/^Thread/p'
2.2 jstack Java 线程栈输出
jstack 是 Java 提供的用于分析 Java 堆栈的工具，可以使用 jps 来获取 Java 的进程号。jstack 可用于生成 Java 虚拟机当前时刻的线程快照，可打印出 JVM 内每一条线程正在执行的方法堆栈的集合，可以用于线程间死锁、死循环、请求外部资源导致的长时间等待的情况。
jstack 是基于语言的层面的展示优化，比通用工具 pstack 的输出更加优化和易于理解。
# jps
16562 HelloWorld
# jstack -l 16562
2021-07-21 14:08:55
Full thread dump OpenJDK 64-Bit Server VM (25.282-b08 mixed mode):
"Attach Listener" #18 daemon prio=9 os_prio=0 tid=0x00007f4090001000 nid=0x4121 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
"Service Thread" #17 daemon prio=9 os_prio=0 tid=0x00007f4118157000 nid=0x40d1 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
Locked ownable synchronizers:
- None
...
"GC task thread#11 (ParallelGC)" os_prio=0 tid=0x00007f4118072800 nid=0x40bf runnable
"GC task thread#12 (ParallelGC)" os_prio=0 tid=0x00007f4118074800 nid=0x40c0 runnable
"VM Periodic Task Thread" os_prio=0 tid=0x00007f4118159800 nid=0x40d2 waiting on condition
JNI global references: 5
2.3 Goang 程序 Goroutine 栈
Golang 语言中采用 GPM 的管理模型，其中 Goroutine 是用户态进行管理的协程，通过逻辑的处理器 P 对象，最终绑定到 M 中进行运行，M 为内核中对应的线程，使用 pstack 跟踪到的为 M 的栈，但是我们更希望看到的 G 的运行栈，这比较贴合我们代码对应的逻辑关系。(在 pprof 中 M 的栈打印为 threadcreate)。
Golang 语言实现中已经提供打印 Goroutine 的功能，可直接使用，实现代码参见这里 。函数签名为 func Stack(buf []byte, all bool)， all 为 bool 类型，如果该参数设置为 true，则表示打印全部的 Goroutine 栈。
runtime.Stack 源码如下：
// Stack formats a stack trace of the calling goroutine into buf
// and returns the number of bytes written to buf.
// If all is true, Stack formats stack traces of all other goroutines
// into buf after the trace for the current goroutine.
func Stack(buf []byte, all bool) int {
if all {
stopTheWorld("stack trace")
}
n := 0
if len(buf) > 0 {
// ...
}
if all {
startTheWorld()
}
return n
}
在 Docker 的实现中，用户可以发送 SIGUSR1 信号量，获取到全部 Goroutine 的栈，实现代码参见函数 setupDumpStackTrap， 通过最终调用的函数 DumpToFile，最后调用
runtime.Stack(buf, true)获取栈。
如果是选择打印全部 Goroutine 栈，需要注意的是整个打印过程是一个 STW 的过程，这一点从代码的实现中也有明确的体现，在排查的程序支持 pprof 模式的情况下，使用 pprof 会更加直观和方便。
go_stack_demo.go 是我提供的一个通过发送 SIGUSR1 信号量打印 goroutine 栈的 go 代码样例。
pprof 访问地址： http://127.0.0.1:6060/debug/pprof/goroutine?debug=1 ; 启用 pprof ，只需要在头部引用包即可：
import ( _ "net/http/pprof" )获取的 goroutine 的底层是通过 handler.ServeHTTP() 函数实现，通过 goroutine 对应的 Profile 结构桥接了入口指令与最终的代码实现 ， 最底层调用函数代码参见这里。
var goroutineProfile = &Profile{ name: "goroutine", count: countGoroutine, write: writeGoroutine, // 读取完整的栈参见这个函数 }
3. 函数级别的调用栈
上述场景我们介绍了系统层面全部运行线程栈、单个程序运行线程栈以及 Golang 语言中的用户级别 Goroutine 栈的输出，已经解决我们遇到的大多数场景，但是还存在我们需要跟踪某个特定函数被调用的栈，比如 sys_read 函数具体被那些函数调用了，调用的频次是怎么样的？ 上述我们介绍的工具就有些勉为其难了，是时候祭出 BPF 利器了。
3.1 被调用函数栈
被调用函数栈表示该函数被其他函数调用的整体运行栈。 BCC 提供的 stackcount 工具，可以实现指定的一个或者一组函数运行栈调用跟踪。如下例子所示，我们使用 stackcount 工具分析内核函数 ip_rcv 被调用的栈。
# ./stackcount ip_rcv
Tracing 1 functions for "ip_rcv"... Hit Ctrl-C to end.
^C
ip_rcv
__netif_receive_skb
process_backlog
net_rx_action
__do_softirq
call_softirq
do_softirq # 软中断开始
irq_exit
smp_call_function_single_interrupt
call_function_single_interrupt
default_idle
arch_cpu_idle
cpu_startup_entry
start_secondary
start_cpu
3
Detaching...
同时 stackcount 工具还支持指定以下条件进行过滤：
-
指定特定进程 PID
-
指定特定的 CPU
-
是否同时跟踪用户空间与内核空间栈
-
跟踪的函数支持表达式和特定的格式
完整的使用帮助如下：
./stackcount -h
usage: stackcount [-h] [-p PID] [-c CPU] [-i INTERVAL] [-D DURATION] [-T] [-r]
[-s] [-P] [-K] [-U] [-v] [-d] [-f] [--debug]
pattern
Count events and their stack traces
positional arguments:
pattern search expression for events
optional arguments:
-h, --help show this help message and exit
-p PID, --pid PID trace this PID only
-c CPU, --cpu CPU trace this CPU only
-i INTERVAL, --interval INTERVAL
summary interval, seconds
-D DURATION, --duration DURATION
total duration of trace, seconds
-T, --timestamp include timestamp on output
-r, --regexp use regular expressions. Default is "*" wildcards
only.
-s, --offset show address offsets
-P, --perpid display stacks separately for each process
-K, --kernel-stacks-only
kernel stack only
-U, --user-stacks-only
user stack only
-v, --verbose show raw addresses
-d, --delimited insert delimiter between kernel/user stacks
-f, --folded output folded format
--debug print BPF program before starting (for debugging
purposes)
examples:
./stackcount submit_bio # count kernel stack traces for submit_bio
./stackcount -d ip_output # include a user/kernel stack delimiter
./stackcount -s ip_output # show symbol offsets
./stackcount -sv ip_output # show offsets and raw addresses (verbose)
./stackcount 'tcp_send*' # count stacks for funcs matching tcp_send*
./stackcount -r '^tcp_send.*' # same as above, using regular expressions
./stackcount -Ti 5 ip_output # output every 5 seconds, with timestamps
./stackcount -p 185 ip_output # count ip_output stacks for PID 185 only
./stackcount -c 1 put_prev_entity # count put_prev_entity stacks for CPU 1 only
./stackcount -p 185 c:malloc # count stacks for malloc in PID 185
./stackcount t:sched:sched_fork # count stacks for sched_fork tracepoint
./stackcount -p 185 u:node:* # count stacks for all USDT probes in node
./stackcount -K t:sched:sched_switch # kernel stacks only
./stackcount -U t:sched:sched_switch # user stacks only
3.2 函数子函数调用（仅支持内核函数）
perf-tools 项目中的 funcgraph 工具可以实现内核函数的子函数调用跟踪，底层技术基于 Linux 的 ftrace 功能，这为我们分析内核函数的调用关系提供了很好的帮助。假如想了解 ip_rcv 函数调用子函数的情况，但是指向子函数调用的 3 级，我们则可以使用以下命令跟踪：
# ./funcgraph -m3 -d4 ip_rcv
Tracing "ip_rcv" for 4 seconds...
0) | ip_rcv() {
0) | nf_hook_slow() {
0) + 16.896 us | nf_iterate();
0) + 17.624 us | }
0) | ip_rcv_finish() {
0) 2.562 us | tcp_v4_early_demux();
0) + 63.073 us | ip_local_deliver();
0) + 67.555 us | }
0) + 86.928 us | }
通过上面的样例，我们发现了 ip_rcv 调用了 nf_hook_slow 和 ip_rcv_finish 等函数流程。同时这个跟踪的输出结果还给出了每段函数调用的耗时时间，这也为慢路径分析提供了非常有利的工具。
但是如果我们跟踪的函数调用频率过高且子函数调用层级没有限制，这种使用方式可能会在生产环境造成性能问题，需按需谨慎使用。
funcgraph 工具也支持按照 pid 进行过滤，完整帮助如下：
# ./funcgraph -h
USAGE: funcgraph [-aCDhHPtT] [-m maxdepth] [-p PID] [-d secs] funcstring
-a # all info (same as -HPt)
-C # measure on-CPU time only
-d seconds # trace duration, and use buffers
-D # do not show function duration
-h # this usage message
-H # include column headers
-m maxdepth # max stack depth to show
-p PID # trace when this pid is on-CPU
-P # show process names & PIDs
-t # show timestamps
-T # comment function tails
eg,
funcgraph do_nanosleep # trace do_nanosleep() and children
funcgraph -m 3 do_sys_open # trace do_sys_open() to 3 levels only
funcgraph -a do_sys_open # include timestamps and process name
funcgraph -p 198 do_sys_open # trace vfs_read() for PID 198 only
funcgraph -d 1 do_sys_open >out # trace 1 sec, then write to file
See the man page and example file for more info.
4. 总结
综上所述，我们对于系统级别、进程级别（包括线程和协程）和函数级别的调用栈跟踪进行了整体介绍，相信对于系统或者进程函数跟踪相关问题的解决提供了一个参考思路。同时基于 statckcount 和 funcgraph 两个工具相互补充，对于我们学习内核函数完整调用链提供了便利。
如果你有更好的跟踪栈或函数调用的方式和使用场景，也欢迎留言。