Por que `time` e `strace -c` diferem?

Um processo pode gastar qualquer quantidade de tempo sem fazer nenhuma chamada de sistema.

Por exemplo, um shell fazendo um while :; do :; donegastará uma quantidade infinita de tempo sem fazer nenhuma chamada de sistema e sem gastar systempo de CPU, apenas usertempo de CPU.

strace -ctenta contar o systempo de CPU por cada chamada do sistema. A nanosleep(1000000000)gastará cerca de 0ms de tempo de CPU, mas 1s de tempo de relógio de parede.

$ bash -c 'time strace -fc sleep 1'
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  [...]
  0.00    0.000000           0         1           nanosleep
  [...]
100.00    0.000000                    33         3 total

real    0m1.006s
user    0m0.001s
sys     0m0.003s

Comparar o tempo do sistema com o tempo relatado pelo strace faria mais sentido, mas observe que nem todo o tempo de CPU do sistema contabilizado para o processo é gasto nesses syscalls. Acessar dados mapeados, por exemplo, pode fazer com que o processo gaste muito tempo do sistema sem fazer nenhuma chamada do sistema.

Aqui, essas inúmeras mmaps()chamadas podem ser para alocar memória. Esses são instantâneos, pois apenas atualizam alguns mapeamentos. Mas a primeira vez que você escreve para eles, é aí que algum tempo do sistema é necessário para fazer backup dessas gravações com a memória real.

Ou podem ser para mapear arquivos de objeto como bibliotecas compartilhadas (essa também é uma possibilidade provável, pois o número não está longe do número de open()s). Então, novamente, o mmap()é rápido, mas ler a memória mais tarde também significa algumas falhas de página e tempo real para ler os dados do disco, o que não é contabilizado em nenhuma chamada do sistema.

Mais fundamentalmente, se você fizer time strace -f your-applicationcomo em uma versão anterior de sua pergunta, timecronometrará o comando e strace.

straceadiciona muita sobrecarga. Ele faz algumas chamadas de sistema para cada chamada de sistema do aplicativo rastreado.

Fazendo

strace -fc time your-application

ao invés de

time strace -fc your-application

é mais provável que lhe dê uma correspondência melhor.

O que descobri, porém, é que para as wait*()chamadas de sistema que os processos fazem para esperar seus filhos, straceconta o tempo relatado por essas wait*()chamadas de sistema como tempo do sistema, o que significa que o tempo dos processos filhos (pelo menos os que são esperados) é contado várias vezes. Isso é importante, strace -f time cmdpois timeé executado cmdem um processo filho e aguarda por ele.

$ strace -c time head -c 100M /dev/urandom > /dev/null
0.00user 0.76system 0:00.76elapsed 99%CPU (0avgtext+0avgdata 1796maxresident)k
0inputs+0outputs (0major+83minor)pagefaults 0swaps
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
100.00    0.762288      762288         1           wait4
  0.00    0.000000           0         1           read
  0.00    0.000000           0       112           write
  0.00    0.000000           0         2           open
  0.00    0.000000           0         2           close
  0.00    0.000000           0         2           fstat
  0.00    0.000000           0         6           mmap
  0.00    0.000000           0         4           mprotect
  0.00    0.000000           0         1           munmap
  0.00    0.000000           0         1           brk
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         3         3 access
  0.00    0.000000           0         1           clone
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
------ ----------- ----------- --------- --------- ----------------
100.00    0.762288                   142         3 total

timee stracerelatar o mesmo horário do sistema (conforme retornado pela wait4()chamada do sistema), mas com -f:

$ strace -fc time head -c 100M /dev/urandom > /dev/null
strace: Process 2298 attached
0.01user 1.33system 0:01.91elapsed 69%CPU (0avgtext+0avgdata 1920maxresident)k
0inputs+0outputs (0major+84minor)pagefaults 0swaps
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 54.60    1.331335     1331335         1           wait4
 39.43    0.961497          75     12804           read
  5.94    0.144825           6     25711           write
  0.01    0.000148          11        13         6 open
  0.00    0.000104           8        13           mmap
  0.00    0.000094          19         5         3 execve
  0.00    0.000063           8         8           mprotect
  0.00    0.000050           6         9           close
  0.00    0.000041           7         6         6 access
  0.00    0.000037           5         7           fstat
  0.00    0.000031          16         2           munmap
  0.00    0.000030           8         4           brk
  0.00    0.000007           4         2           arch_prctl
  0.00    0.000006           6         1         1 ioctl
  0.00    0.000000           0         4           rt_sigaction
  0.00    0.000000           0         1           clone
------ ----------- ----------- --------- --------- ----------------
100.00    2.438268                 38591        16 total

O 1,33 é o tempo relatado pela única wait4()chamada de sistema que o timefaz. Isso informa o tempo do sistema de head( timefilho de).

No entanto, stracetambém tenta obter o tempo do sistema para cada syscall de seu headneto, o que significa que é contado duas vezes (não exatamente). Esse traçado do neto ainda incorre em alguma sobrecarga contabilizada no processo traçado, pois obtemos 1,33 em oposição a 0,76 anteriormente. Isso é consideravelmente reduzido se eu forçar strace, time e head a rodar no mesmo processador (com taskset 1).