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표시되지 않기 때문입니다. 시스템 호출의 실행 시간에 관심이 있는 경우 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 버전을 호출할 때(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 라이브러리 함수를 호출 clock_gettime하고 두 번째 경우 프로그램은 clock_gettimevDSO를 호출하는 C 라이브러리 함수를 호출합니다. 두 clock_gettime호출은 다르지만 추적에서는 동일하게 나타납니다.

내가 이해한 바에 따르면 보고된 시간에는 syscall보고된 시간이 포함되어 있으며 SYS_clock_gettime이는 백분율 표시가 오해의 소지가 있음을 의미합니다. 이 내용은 설명서에 나와 있지 않으며 소스 코드를 모두 읽지 않았기 때문에 틀렸을 수도 있습니다.

ltrace고려해야 할 또 다른 점은 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 버전의 경우.

관련 정보