Linux

使用 ltrace 計時系統呼叫:添加 syscall + clock_gettime

  • February 27, 2022

我正在尋找系統呼叫方面的一些清晰度。我嘗試通過直接呼叫系統呼叫來避免 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

如果我不從第一個程序的輸出中添加syscallclock_gettime條目,那麼呼叫系統呼叫所需的總時間clock_gettime(12 微秒/呼叫)實際上比我在第二個中呼叫 vDSO 版本(43 微秒/呼叫)時要低程序。在我看來,這沒有任何意義。只有當第一個程序的呼叫需要大約 80 微秒/呼叫(添加兩個條目)時才有意義,因為 vDSO 應該加速這一點。

我知道在這個系統(核心 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呼叫,睡眠時間會加倍,這沒有任何意義。我對麼?

我懷疑一些混亂歸結為命名。在我的系統上,強制系統呼叫會產生這種風格的跟踪:

% 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;這也意味著百分比顯示具有誤導性。這不在文件中,而且我還沒有閱讀所有原始碼,所以我可能錯了。

要考慮的另一點是由ltraceincludeltrace的成本測量的時間。其他分析工具,例如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 版本。

引用自:https://unix.stackexchange.com/questions/692273