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など)と呼び出し回数を使用します。たとえば、次のコードスニペットはclock_gettime時計を100回呼び出します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表示されないためです。システムコールの実行時間に興味がある場合とsyscall情報clock_gettimeを追加する必要がありますか?何らかの理由で、この問題はAmazon Linux 2で実行している場合にのみ発生します。マイコンピュータのUbuntu VMで実行すると、SYS_clock_gettime期待どおりに1つのエントリしか表示されません。

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合計時間は、2番目のプログラムでvDSOバージョンを呼び出すとき(43usecs)よりも短くなります(12usecs / call)。 /call)プログラムです。私の考えでは、これは言葉ではありません。 vDSOがプロセスを高速化する必要があるため、最初のプログラムの呼び出しが呼び出しごとに約80usecs(2つのエントリを追加)の場合にのみ意味があります。clock_gettimeclock_gettime

clock_gettimeこのシステム(カーネル5.10)では、次のコードスニペットを実行しても出力が出ないため、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通話を同時にすれば睡眠時間が2倍に増えるのは言えません。私は正しいですか?

答え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

最初の場合、プログラムはシステムコールをsyscall呼び出すCライブラリ関数を呼び出し、2番目のclock_gettime場合、プログラムはclock_gettimevDSOを呼び出すCライブラリ関数を呼び出します。両方clock_gettimeの呼び出しは異なりますが、トレースでは同じように見えます。

私が理解したところ、報告された時間には報告されたsyscall時間が含まれてSYS_clock_gettimeいます。これはドキュメントに記載されておらず、ソースコードをすべて読んでいないため、間違っている可能性があります。

ltrace考慮すべきもう1つの点は、ltrace包含オーバーヘッドで測定される時間です。他の分析ツール(例)は、perf statvDSOが実際に高速であることを示しています。

             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 バージョンの場合。

関連情報