O poderoso strace
me decepcionou. Como isso é possível?
time foo
mostra que foo
leva vários segundos para rodar ("real"), mas usa tempo de CPU insignificante, tanto no espaço do usuário ("usuário") quanto no kernel ("sys"). Para os curiosos, foo
é definido abaixo.
Portanto, ele passa a maior parte do tempo esperando por outra coisa, não executando as instruções da CPU. Normalmente, posso ver como ele está esperando strace
- ou seja, qual chamada do sistema está bloqueando por um longo período de tempo. Infelizmente, essa abordagem não funcionou.
strace -ttt -T -C -w foo
mostra chamadas de sistema, data e hora e um resumo do tempo (real) gasto em chamadas de sistema. Mas esse processo em particular mostrou um gasto de tempo geral (real) insignificante dentro das chamadas do sistema.
foo
é na verdade journalctl -b -u dev-hugepages.mount
. Exceto que eu tive que mudar o último argumento para uma unidade systemd diferente a cada vez para reproduzir isso. Em outras palavras, o atraso que estou investigando aconteceu na primeira vez que tentei obter os logs de qualquer unidade systemd. EDIT : depois de responder a pergunta principal, também percebi o motivo pelo qual estava tendo esse problema ao reproduzir o atraso .
O tempo gasto nesse processo é um problema específico, aparentemente não ocorre em todos os sistemas. https://github.com/systemd/systemd/issues/7963
O motivo usual para atingir esse problema é que o processo está bloqueando em falhas de página. Estas são leituras ou possivelmente gravações em arquivos executadas por meio de um mapeamento de memória, também conhecido como
mmap()
. Você deve ter notado algunsmmap()
no rastreamento de chamadas do sistema.Se você tivesse usado o
/usr/bin/time
programa em vez dotime
shell embutido, também deve ter notado:major
pagefaults são aqueles que requerem IO do sistema de arquivos.minor
pagefaults são muito menos significativos (provavelmente apenas uma "falha TLB").Eu suspeito que
inputs
são o número total de páginas lidas. Atualmente, acho que as páginas mapeadas de arquivo são sempre do mesmo tamanho. 4096 bytes na maioria dos casos, mas você pode verificargetconf PAGESIZE
.Isso representa aproximadamente 290 megabytes, lidos em algo acima de 100 megabytes por segundo, uma velocidade padrão para um disco rígido como o meu. Mistério resolvido!
Observe também que você está assumindo que possui uma CPU totalmente livre para este processo. Caso contrário, o processo pode simplesmente ser bloqueado esperando que outros processos cedam a CPU.
strace
mostra apenas quando o processo entra (e sai) do kernel devido a uma chamada do sistema. Ou quando um sinal unix é entregue. No entanto, existem outros tipos de interrupções questrace
não aparecem. Então, estes incluem