Interpretando os horários mostrados em um strace para chamadas abertas do sistema

Question

Estamos com problemas de latência em um aplicativo de fornecedor. Eu corri um strace -Tttt no processo e recebi isso:

[...]
1470166748.946144 open("/opt/app/shdbrth/X       ", O_RDONLY) = -1 ENOENT (No such file or directory) <0.000016>
1470166800.850979 open("/opt/app/shdbrth/X38347", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 10 <0.000070>
1470166800.851139 fstat(10, {st_mode=S_IFREG|0660, st_size=0, ...}) = 0 <0.000006>
[...]

De acordo com a página de manual , o -ttt prefixa cada linha com a hora em que o syscall foi criado. A opção -T acrescenta o tempo que a chamada levou para processar entre os colchetes < e > . No entanto, isso não parece se encaixar no exemplo acima.

Por exemplo, a segunda linha começou em 1.470.166.800 épocas e 850.979 microsegundos. De acordo com o cronômetro acrescentado, foram necessários 70 microsecs para serem processados. No entanto, a próxima linha começa nos mesmos segundos da época e 851,139 microsecs --- uma diferença de 90 microsecs.

Eu ia escrever isso apenas na parte de cima, mas talvez haja uma explicação mais precisa.

    

Answer 1

A hora no início da linha é a hora em que o kernel começou a processar a chamada do sistema. A duração no final da linha é o intervalo entre o momento em que o kernel começou a processar a chamada do sistema e a hora em que o kernel respondeu à chamada do sistema.

A hora no início da próxima linha é a hora em que o kernel começou a processar a próxima chamada do sistema. Entre a resposta a uma chamada do sistema e a entrada na próxima chamada do sistema, ocorreram dois tipos de coisas: o processo executou o código do usuário e, potencialmente, outros processos foram agendados no mesmo processador.

No seu exemplo, a primeira chamada open levou 16µs, e a próxima chamada foi emitida cerca de 12s depois. Durante esses doze segundos, o processo executou o código do usuário e, provavelmente, foi impedido várias vezes de executar outros processos. Entre a segunda open call e a subseqüente fstat , cerca de 90 µs passaram; Dado o quão pequeno isso é, isso sugere que o processo executou apenas uma pequena quantidade de código de usuário e não foi preterido.