如何获得我的程序的内核执行时间的详细细分？

Question

我有一个程序，可以执行一些AI推理任务。

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

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

Answer 1

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

如果您没有访问源代码的权限，或者您只对syscall感兴趣，您可以尝试使用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.