2

我正在跟踪各种内核函数和系统调用，并在它们之间建立可用于某些性能分析的模式。

我注意到的一件事是，有时，即使在我的简单测试应用程序中，它启动了一些与一些互斥锁一起使用的线程，我也不会收到任何kretprobe__sys_futex对kprobe__sys_futex.

我假设这是因为例如一个线程正在调用sys_futex，并进入睡眠状态或可能终止，但我实际上看到相同的进程sys_futex连续多次调用，而返回探针却没有注意到任何事情。

然后我假设问题在于我如何过滤对 的调用kprobe__sys_futex，所以我使用 BCC/eBPF 做了一个最小的例子来测试这个：

#! /usr/bin/env python

from bcc import BPF

b = BPF(text="""
BPF_HASH(call_count, int, int);

int kprobe__sys_futex() {
  int zero = 0;
  call_count.lookup_or_init(&zero, &zero);
  bpf_trace_printk("futex start\\n");
  call_count.increment(zero);
  return 0;
}

int kretprobe__sys_futex() {
  int zero = 0;
  int *val_p = call_count.lookup(&zero);
  if (val_p != NULL) {
      int val = *val_p;
      val--;
      call_count.update(&zero, &val);
      bpf_trace_printk("futex calls with no return: %d\\n", val);
  } else { bpf_trace_printk("unexpected futex return\\n"); }
  return 0;
}
""")

b.trace_print()

我注意到在各种应用程序中（一个很好的例子是 mysql-server，即使在空闲时也会执行常规的 futex 操作 - 至少在我的机器上），futex start在返回探针的消息之前会打印许多（通常是 10+）s。

这是我在写这篇文章时运行了几分钟的上述程序的示例跟踪：

... hundreds of lines of much the same as below
           gdbus-612   [001] .... 211229.997665: 0x00000001: futex start
  NetworkManager-541   [001] .... 211229.997667: 0x00000001: futex start
           gdbus-612   [001] .... 211229.997670: 0x00000001: futex start
          mysqld-697   [001] .... 211230.789205: 0x00000001: futex start
          mysqld-697   [001] .... 211230.789227: 0x00000001: futex start
          mysqld-703   [001] .... 211230.789251: 0x00000001: futex start
          mysqld-703   [001] .... 211230.789253: 0x00000001: futex start
          mysqld-704   [001] d... 211230.789258: 0x00000001: futex calls with no return: 3994
          mysqld-704   [001] .... 211230.789259: 0x00000001: futex start
          mysqld-704   [001] d... 211230.789260: 0x00000001: futex calls with no return: 3994
          mysqld-704   [001] .... 211230.789272: 0x00000001: futex start
          mysqld-713   [000] .... 211231.037016: 0x00000001: futex start
          mysqld-713   [000] .... 211231.037036: 0x00000001: futex start
         vmstats-895   [000] .... 211231.464867: 0x00000001: futex start
          mysqld-697   [001] .... 211231.790738: 0x00000001: futex start
          mysqld-697   [001] .... 211231.790784: 0x00000001: futex start
          mysqld-703   [001] .... 211231.790796: 0x00000001: futex start
          mysqld-703   [001] .... 211231.790799: 0x00000001: futex start
          mysqld-704   [001] d... 211231.790809: 0x00000001: futex calls with no return: 4001
          mysqld-704   [001] .... 211231.790812: 0x00000001: futex start
          mysqld-704   [001] d... 211231.790814: 0x00000001: futex calls with no return: 4001

如您所见，例如 pid 697 似乎已经调用了sys_futex四次，而仅在这个小跟踪中没有返回。

我认为这不是 eBPF 代码中的竞争条件，因为如果您将打印语句静音并且只定期打印，则计数通常会在零附近的几个范围内sys_write，这比sys_futex（至少在我的系统的工作负载上）更频繁地发生)，所以我希望任何竞争条件都会加剧而不是解决。

我在位于 VirtualBox 的 Ubuntu 18.04 LTS 上运行内核 4.15.0-43-generic。

很高兴提供更多可能有用的上下文！

IOVisor 邮件列表中有一个相关的主题：https ://lists.iovisor.org/g/iovisor-dev/topic/29702757

4

1 回答 1

1

这是 bcc 的已知限制（参见iovisor/bcc#1072）。基本上，对于您的跟踪上下文，活动探测的最大数量设置得太低，因此您会丢失一些返回探测。

在 bcc 中，该maxactive值（活动探测的最大数量，请参阅下面的文档摘录）保留为默认值。由于 Alban Crequy 的 Linux 内核补丁（参见iovisor/bcc#1072maxactive ），因此可以在通过 debugfs 附加探针时更改该值。不过，该新 API 尚未通过密件抄送公开。这周我会尝试发送一个补丁来实现这个效果。

当被探测函数正在执行时，它的返回地址存储在一个 kretprobe_instance 类型的对象中。在调用 register_kretprobe() 之前，用户设置 kretprobe 结构的 maxactive 字段来指定可以同时探测多少个指定函数的实例。register_kretprobe() 预分配指定数量的 kretprobe_instance 对象。

例如，如果函数是非递归的并且在调用时持有自旋锁，那么 maxactive = 1 就足够了。如果函数是非递归的并且永远不会放弃 CPU（例如，通过信号量或抢占），NR_CPUS 应该足够了。如果 maxactive <= 0，则设置为默认值。如果启用了 CONFIG_PREEMPT，则默认值为 max(10, 2*NR_CPUS)。否则，默认值为 NR_CPUS。

于 2019-02-17T15:16:24.280 回答