命令“strace -T”引入了太多开销

Question

我正在尝试使用 strace -T 检查应用程序调用的每个系统调用的执行时间。

我得到了跟踪输出。但是 strace 为每个系统调用计算的时间似乎不准确。

为了确认准确性，我在应用程序中添加了一些 usleep(100) 调用。 usleep 正在调用 nanosleep() 系统调用。 我预计 strace 显示 nanosleep(100000) 所花费的时间约为 100 微秒。但 strace 显示的 nanosleep(100000) 值约为 300 微秒。对于某些调用，它甚至显示 7 毫秒（如下面所附屏幕截图的第三行所示）。

1. 系统调用的执行时间波动这么大的原因是什么？这是 strace 计算的问题还是 nanosleep(100000) 的执行时间确实超过 100 微秒？
2. 如果问题是由于 strace 引入的开销造成的，则开销太大，strace 无法用于计算系统调用所花费的时间。有什么办法可以避免 strace 的开销吗？如果没有，有没有其他工具可以达到同样的效果？

Answer 1

strace

相当具有侵入性，因为它是建立在

ptrace

（即 手册页）之上的。直接的含义是

strace

遭受用户空间和内核空间之间的交互 - 这是因为

ptrace

只不过是另一个系统调用，并带来了所有后果。

eBPF 的全部特点是它完全在内核空间中运行，两个世界之间没有代价高昂的交互。您可以尝试使用 bpftrace 进行实验并比较结果（强烈倾向于后者比前一个更值得信赖）。根据我的经验，eBPF 不仅速度更快、资源消耗更少，而且也更准确。

如果您是 eBPF 新手并且不知道它是什么，那么 从这里开始。

Answer 2

追踪

这似乎很可能是由 strace 引起的。默认情况下，strace 拦截所有系统调用条目并退出，导致每个系统调用进行两次上下文切换。

如果您想跟踪系统调用的子集，可以使用一个实验性选项来减少开销，

--seccomp-bpf

。有关说明，请参阅 https://pchaigno.github.io/strace/2019/10/02/introducing-strace-seccomp-bpf.html。

密件抄送

对于您的情况，一种选择是使用现有的密件抄送工具

funclatency

。请参阅 https://github.com/iovisor/bcc/blob/master/tools/funclatency_example.txt 了解其用法示例。

您还可以通过软件包安装 funclatency（在 Ubuntu 上为

bpfcc-tools

）。跟踪 nanosleep(2) 系统调用的延迟将是：

# funclatency-bpfcc __x64_sys_nanosleep
Tracing 1 functions for "__x64_sys_nanosleep"... Hit Ctrl-C to end.
^C
     nsecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 0        |                                        |
      1024 -> 2047       : 0        |                                        |
      2048 -> 4095       : 0        |                                        |
      4096 -> 8191       : 0        |                                        |
      8192 -> 16383      : 0        |                                        |
     16384 -> 32767      : 0        |                                        |
     32768 -> 65535      : 0        |                                        |
     65536 -> 131071     : 5        |*                                       |
    131072 -> 262143     : 0        |                                        |
    262144 -> 524287     : 0        |                                        |
    524288 -> 1048575    : 0        |                                        |
   1048576 -> 2097151    : 0        |                                        |
   2097152 -> 4194303    : 0        |                                        |
   4194304 -> 8388607    : 0        |                                        |
   8388608 -> 16777215   : 132      |****************************************|

avg = 9766470 nsecs, total: 1338006501 nsecs, count: 137

Detaching...

如果您想将延迟显示为参数的函数，那么您可以编辑

funclatency.py

脚本或使用bpftrace重写某些内容。