如何详细了解我的程序的内核执行时间？答案

【问题标题】：How to get a detailed breakdown of the kernel execution time of my program?如何详细了解我的程序的内核执行时间？
【发布时间】：2021-05-26 18:03:33
【问题描述】：

我有一个执行一些 AI 推理任务的程序。

使用time(1) 命令，我发现它在内核中花费了相当多的时间（即time(1) 输出的system 时间）。

有没有办法找到这次更详细的细分？例如，在系统调用、上下文切换、I/O 交互等方面花费了多少时间。

【问题讨论】：

man perf 这就是你需要的。在某些 CPU 上，您将获得更好的覆盖范围，因为它们具有对（分支）跟踪的硬件支持。

标签： linux linux-kernel profiling

【解决方案1】：

我相信最好的方法是分析源代码，例如，如果这是你正在运行的 python 程序，你可以使用 cProfile。

如果您无权访问源代码或者您只对系统调用感兴趣，您可以尝试使用strace (1)。

要打印每个系统调用所用时间的摘要，请使用-c 标志：

$ strace -c -f ls
some random files
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 31.91    0.000150           6        27           mmap
 17.02    0.000080           4        18           mprotect
 15.74    0.000074           7        10           open
  8.09    0.000038           3        11           fstat
  7.66    0.000036           5         8           read
  6.60    0.000031           2        13           close
  2.77    0.000013          13         1           write
  2.77    0.000013          13         1           openat
  2.55    0.000012           6         2           getdents
  2.34    0.000011           6         2         1 access
  1.70    0.000008           4         2           munmap
  0.43    0.000002           1         2           ioctl
  0.43    0.000002           2         1           arch_prctl
  0.00    0.000000           0         1           stat
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0         2           statfs
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
------ ----------- ----------- --------- --------- ----------------
100.00    0.000470                   111         1 total

如果您想准确了解每次系统调用花费了多少时间，可以使用-T 标志（时间在右侧）：

$ strace -T -f ls
execve("/usr/bin/ls", ["ls"], [/* 49 vars */]) = 0 <0.000183>
brk(NULL)                               = 0x2066000 <0.000016>
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f7fbe67d000 <0.000012>
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory) <0.000011>
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3 <0.000012>
fstat(3, {st_mode=S_IFREG|0644, st_size=121028, ...}) = 0 <0.000011>
mmap(NULL, 121028, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f7fbe65f000 <0.000010>
close(3)                                = 0 <0.000006>
open("/lib64/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3 <0.000014>

[...]

来自手册页：

 -f          Trace child processes as they are created by currently  traced  processes
                   as  a  result  of  the fork(2), vfork(2) and clone(2) system calls.

 -c          Count time, calls, and errors for each system call and report  a  summary
                   on  program  exit.

-T          Show  the  time  spent in system calls.  This records the time difference
                   between the beginning and the end of each system call.

【讨论】：