使用 ltrace 计时系统调用:添加 `syscall` + `clock_gettime`?

使用 ltrace 计时系统调用:添加 `syscall` + `clock_gettime`?

我正在寻找系统调用方面的一些清晰度。我尝试通过直接调用系统调用来避免 vDSO clock_gettime。这是一个名为 的程序的片段sys_clock_gettime

int clock = CLOCK_MONOTONIC;
struct timespec ts;
if (syscall(__NR_clock_gettime, clock, &ts) == -1){
  exit(-1); 
}

该程序采用时钟的名称(CLOCK_BOOTTIME, CLOCK_MONOTONIC等)和要进行的许多调用。例如,下面的代码片段将调用 100 次clock_gettime时钟CLOCK_BOOTTIME

./sys_clock_gettime CLOCK_BOOTTIME 100

我尝试用它ltrace来弄清楚发生了什么:

ltrace -cS ./sys_clock_gettime CLOCK_BOOTTIME 100
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 77.41    0.006887          68       100 syscall
 14.32    0.001274          12       100 clock_gettime
  1.79    0.000159         159         1 brk
  1.17    0.000104         104         1 exit
  1.16    0.000103          51         2 strcmp
  0.82    0.000073          14         5 mmap
  0.65    0.000058          14         4 mprotect
  0.61    0.000054          54         1 exit_group
  0.51    0.000045          45         1 atoi
  0.31    0.000028          14         2 openat
  0.30    0.000027          13         2 fstat
  0.29    0.000026          13         2 close
  0.19    0.000017          17         1 munmap
  0.17    0.000015          15         1 access
  0.16    0.000014          14         1 read
  0.15    0.000013          13         1 arch_prctl
------ ----------- ----------- --------- --------------------
100.00    0.008897                   225 total

由于某种原因,既有syscall条目又有clock_gettime条目。您可以看出这syscall是一个库条目,而这clock_gettime是一个系统调用条目,因为如果您禁用-S其中的模式,ltrace它将不会显示。如果我对系统调用的执行时间感兴趣,我应该添加syscallclock_gettime信息吗?由于某种原因,这只发生在我在 Amazon Linux 2 中运行此程序时,当在我自己的计算机中的 Ubuntu VM 中运行时,我只得到一个SYS_clock_gettime条目,正如我所期望的那样。

vdso_clock_gettime现在,将其与另一个具有相同参数的程序(我们称之为 )进行比较。

ltrace -cS ./vdso_clock_gettime CLOCK_BOOTTIME 100
% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 85.82    0.004340          43       100 clock_gettime
  3.08    0.000156         156         1 brk
  2.02    0.000102          51         2 strcmp
  1.90    0.000096          96         1 exit
  1.38    0.000070          14         5 mmap
  1.13    0.000057          14         4 mprotect
  0.97    0.000049          49         1 exit_group
  0.93    0.000047          47         1 atoi
  0.59    0.000030          15         2 openat
  0.51    0.000026          13         2 fstat
  0.51    0.000026          13         2 close
  0.32    0.000016          16         1 access
  0.32    0.000016          16         1 munmap
  0.26    0.000013          13         1 read
  0.26    0.000013          13         1 arch_prctl
------ ----------- ----------- --------- --------------------
100.00    0.005057                   125 total

如果我不添加第一个程序输出中的syscall和条目,那么调用系统调用所需的总时间实际上比我在第二个程序中调用 vDSO 版本(43 usecs/调用)要低(12 usecs/调用)程序。在我看来,这没有意义。仅当第一个程序的调用每次调用大约 80 usecs(两个条目相加)时才有意义,因为 vDSO 应该会加速这一过程。clock_gettimeclock_gettime

我知道在这个系统(内核 5.10)中,clock_gettime是通过 vDSO 加速的,因为当我运行下面的代码片段时,我没有得到任何输出:

strace -e clock_gettime,gettimeofday -- date >/dev/null
+++ exited with 0 +++

我不确定这是否相关,但时钟源设置为tsc.对这里发生的事情有什么想法吗?

编辑:查看实际的跟踪,我开始认为对的调用syscall包括两者。

syscall(228, 7, 0x7ffd270f9c80, 0x1999999999999999 <unfinished ...>
clock_gettime@SYS(7, 0x7ffd270f9c80, 0x1999999999999999, 0x7ffd270fa70a) = 0
<... syscall resumed> )  

我还尝试过nanosleep,如果我同时计算syscallnanosleep通话,睡眠时间会加倍,这是没有意义的。我对么?

答案1

我怀疑一些混乱是由于命名造成的。在我的系统上,强制系统调用会产生以下样式的跟踪:

% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 84.10    0.005402          54       100 syscall
 10.14    0.000651           6       100 SYS_clock_gettime
  1.87    0.000120          17         7 SYS_mmap
  0.97    0.000062          62         1 SYS_brk
  0.72    0.000046          11         4 SYS_mprotect
  0.47    0.000030          30         1 SYS_access
  0.45    0.000029          29         1 SYS_read
  0.37    0.000024          12         2 SYS_fstat
  0.31    0.000020          10         2 SYS_openat
  0.26    0.000017          17         1 SYS_munmap
  0.23    0.000015           7         2 SYS_close
  0.11    0.000007           7         1 SYS_arch_prctl
------ ----------- ----------- --------- --------------------
100.00    0.006423                   222 total

使用 vDSO 会生成以下样式的跟踪:

% time     seconds  usecs/call     calls      function
------ ----------- ----------- --------- --------------------
 93.17    0.004158          41       100 clock_gettime
  1.66    0.000074          74         1 SYS_access
  1.61    0.000072          10         7 SYS_mmap
  0.92    0.000041          10         4 SYS_mprotect
  0.72    0.000032          16         2 SYS_openat
  0.56    0.000025          25         1 SYS_brk
  0.36    0.000016           8         2 SYS_close
  0.34    0.000015           7         2 SYS_fstat
  0.34    0.000015          15         1 SYS_munmap
  0.18    0.000008           8         1 SYS_read
  0.16    0.000007           7         1 SYS_arch_prctl
------ ----------- ----------- --------- --------------------
100.00    0.004463                   122 total

第一种情况,程序调用C库syscall函数,该函数调用clock_gettime系统调用;在第二种情况下,程序调用C库clock_gettime函数,该函数调用vDSO。这两个clock_gettime调用不同,但它们在您的跟踪中显示相同。

据我了解,报告的时间syscall确实包括报告的时间SYS_clock_gettime;这也意味着百分比显示具有误导性。文档中没有涵盖这一点,而且我还没有阅读所有源代码,所以我可能是错的。

ltrace另一点需要考虑的是,通过includeltrace的开销测量的时间。其他分析工具(例如)perf stat表明 vDSO 确实更快:

             42.13 msec task-clock                #    0.988 CPUs utilized          
                 4      context-switches          #    0.095 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
                44      page-faults               #    0.001 M/sec                  
       138,771,425      cycles                    #    3.294 GHz                      (71.53%)
        38,690,379      instructions              #    0.28  insn per cycle           (71.57%)
         7,599,904      branches                  #  180.377 M/sec                    (81.14%)
           300,729      branch-misses             #    3.96% of all branches          (75.76%)

       0.042636471 seconds time elapsed

       0.015510000 seconds user
       0.027143000 seconds sys

通常用于系统调用版本(超过 100,000 次调用),以及

              4.84 msec task-clock                #    0.815 CPUs utilized          
                 0      context-switches          #    0.000 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
                48      page-faults               #    0.010 M/sec                  
         6,257,648      cycles                    #    1.294 GHz                      (50.28%)
         9,019,370      instructions              #    1.44  insn per cycle         
         1,925,045      branches                  #  398.113 M/sec                  
             1,594      branch-misses             #    0.08% of all branches          (49.72%)

       0.005934008 seconds time elapsed

       0.003025000 seconds user
       0.003025000 seconds sys

对于 vDSO 版本。

相关内容