Um processo pode gastar qualquer quantidade de tempo sem fazer nenhuma chamada do sistema.
Por exemplo, um shell fazendo um while :; do :; done gastará uma quantidade infinita de tempo sem fazer qualquer chamada de sistema e sem gastar sys tempo de CPU, apenas user de tempo de CPU.
strace -c tenta contar o tempo de CPU sys em cada chamada de sistema. Um nanosleep(1000000000) gastará perto do tempo de CPU de 0 ms, mas de um 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 de sys com o tempo reportado pelo strace faria mais sentido, mas note que nem todo tempo de CPU do sistema contabilizado no processo é gasto nesses syscalls. Acessar dados mmaped por exemplo pode fazer com que o processo gaste muito tempo do sistema sem fazer qualquer chamada de sistema.
Aqui, essas numerosas chamadas de mmaps() poderiam ser para alocar memória. Esses são instantâneos, pois apenas atualizam alguns mapeamentos. Mas a primeira vez que você escreve para eles, é onde é necessário algum tempo do sistema para fazer essas gravações com memória real.
Ou eles podem ser para mapear arquivos de objetos como bibliotecas compartilhadas (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 posteriormente significa também 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ê usar time strace -f your-application como em uma versão anterior de sua pergunta, time determinará o tempo e o comando strace .
strace adiciona muita sobrecarga. Ele faz algumas chamadas de sistema para cada chamada de sistema do aplicativo straced.
Fazendo
strace -fc time your-application
em vez de
time strace -fc your-application
é mais provável que você tenha uma correspondência melhor.
O que eu acho é que, para as chamadas do sistema wait*() que os processos fazem esperar seus filhos, strace conta o tempo relatado por essas wait*() chamadas do sistema como hora do sistema, o que significa que o tempo das crianças processos (pelo menos os que são esperados) são contados várias vezes. Isso é importante em strace -f time cmd , pois time executa cmd em um processo filho e espera 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
time e strace informam o mesmo horário de sys (conforme retornado pela chamada de sistema wait4() ), 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 informado pela chamada do sistema wait4() que time faz. Isso informa o tempo de sys de head ( time 's filho).
No entanto, strace também tenta obter a hora do sistema para cada syscall de seu head neto além disso, o que significa que é contado duas vezes (não exatamente). Esse esforço do grande filho ainda incorre em alguma sobrecarga responsável pelo processo, já que temos 1,33 em vez de 0,76 anteriormente. Isso é consideravelmente reduzido se eu forçar strace, time e head a rodar no mesmo processador (com taskset 1 ).