使用 ftrace 跟踪内核函数调用栈

搞虚拟化的,经常会遇到很多和内核相关的线上问题。比如最近我们遇到一个 k8s 的 pod 在删除的时候 pvc 卸载不掉的情况。

umount 的时候提示挂载点已经 not mounted 了,但是在 /proc/mounts 里仍然存在。statvfs 看了一下,这个挂载点的device id和父目录的device id 是一样的,说明已经不是挂载点了(因为看 /proc/mounts,这个挂载点的src是在另外一个设备上)

特别注意:如果 /proc/mounts 里,src 和 dst 是同一个设备,那就是 –bind 的方式,这种情况下就很难判断挂载点是否已经真正的卸载掉了

针对这个问题,社区已经有了一个比较 hack 的解决方案:https://github.com/kubernetes/kubernetes/issues/114546,就是忽略 /proc/mounts 残留,允许 pod 删除流程继续往下走

但是根源还是内核的存在脏数据(大概率猜测可能是引用计数泄露导致),还是得从内核层面定位这种问题,而且这种问题,很多时候我们得知道内核代码的执行路径是什么样的。这个时候用 ftrace 来定位就很方便了,比 eBPF 好使,ftrace 能够直接跟踪一个内核函数的调用栈

用法很简单:

  1. 打开 function_graph:echo function_graph > /sys/kernel/debug/tracing/current_tracer
  2. 指定要跟踪的函数:echo do_umount > /sys/kernel/debug/tracing/set_graph_function
    1. 确保 /sys/kernel/debug/tracing/set_ftrace_filter 是空的,不然看不到完整的栈,只能输出这里指定的函数
  3. 开始跟踪:echo 1 > /sys/kernel/debug/tracing/tracing_on,注意如果定位完了,一定要 echo 0 关闭掉
  4. 获取输出:cat /sys/kernel/debug/tracing/trace

最后得到的 trace 结果是这样的:

有了这个调用栈,内核函数的执行路径就一目了然了,因为内核走不到的分支这里不会打印出来(注意内核有很多 inline 函数也不会展示,编译优化掉了)

除此之外,如果想跟踪特定的进程的操作,可以使用 /sys/kernel/debug/tracing/set_ftrace_pid 接口指定 pid


Concurrency management in BPF

eBPF 对并发编程的支持是非常弱的

有一些讨论:

  1. https://lists.iovisor.org/g/iovisor-dev/topic/bpf_concurrency/74407447
  2. https://lwn.net/Articles/779120/

但是你甚至在 eBPF 的官方文档 https://github.com/iovisor/bcc/blob/master/docs/reference_guide.md 里面几乎找不到任何关于并发的描述,除了 map.atomic_increment() 接口

但是这个借口也很奇怪。为了突出这个接口是原子的,线程安全的,难道其他接口就不是了吗?但好像又不是,因为 eBPF 里有大量的示例,并没有对 map 做特殊的并发控制,所以理论上可以认为,其他大部分 map 操作接口,也是线程安全的

线程安全验证

测试代码如下:

// calculate latency
int trace_run(struct pt_regs *ctx, struct task_struct *prev)
{
    u32 pid = bpf_get_current_pid_tgid();
    u64 *tsp;
    if (pid <= 1) {
        return 0;
    }
    
    pid = 10000; 
    u64 ts = bpf_ktime_get_ns();
    start.update(&pid, &ts);
   
#define __OP__ == 
    tsp = start.lookup(&pid); if (tsp __OP__ 0) { dist.increment(bpf_log2l(1)); }
    tsp = start.lookup(&pid); if (tsp __OP__ 0) { dist.increment(bpf_log2l(1)); }
    /** 重复N次 **/
    tsp = start.lookup(&pid); if (tsp __OP__ 0) { dist.increment(bpf_log2l(1)); }
    tsp = start.lookup(&pid); if (tsp __OP__ 0) { dist.increment(bpf_log2l(1)); }
    
    start.delete(&pid);
    return 0;
}

这段代码,修改自 bbc 工具集自带的 runqlat.py

这段代码实际上是在构造一个冲突场景,来验证 trace_run 到底是并行执行还是串行执行的。代码的逻辑是在一个超高频触发的钩子(调度器进行上下文切换)函数里,先在 map 里插入一个固定key(pid)的元素,然后查询 N 次,每次查询如果 key 不存在,计数器就 +1,最后把 key 从 map 里面删除掉,如果:

  1. trance_run 是串行的,那么技术器永远都是 0,因为在一个串行执行的逻辑里,插入元素后,不管查询多少次,元素必然是存在的
  2. 如果 trace_run 是并行的,那么就存在一个条件,一定有一个 cpu,在另外一个 cpu 查询 key 是否存在的时候,执行到了函数结束的地方,把 key 从 map 里面删掉了

事实证明,trace_run 是并行执行的,并且中间 lookup 的次数越多,冲突的概率就越大