Enquete do Linux () com 1 fd lento após uma gravação, rápida após uma leitura

Question

Problema

Estou observando que poll() das chamadas estão tomando milissegundos quando são chamadas imediatamente após uma operação write() , ainda levando apenas microssegundos quando chamadas imediatamente após uma operação read() .

Isso está no código que usa a biblioteca de comunicação ACE C ++.

Estou tentando entender por que existe uma diferença tão significativa no tempo de CPU do sistema para chamar poll() após uma chamada write() em comparação com uma chamada read() .

Sistema

[root@host ~]# lsb_release -a
LSB Version:    :core-4.0-amd64:core-4.0-ia32:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-ia32:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-ia32:printing-4.0-noarch
Distributor ID: RedHatEnterpriseServer
Description:    Red Hat Enterprise Linux Server release 5.9 (Tikanga)
Release:    5.9
Codename:   Tikanga

strace

write(234, "
[root@host ~]# lsb_release -a
LSB Version:    :core-4.0-amd64:core-4.0-ia32:core-4.0-noarch:graphics-4.0-amd64:graphics-4.0-ia32:graphics-4.0-noarch:printing-4.0-amd64:printing-4.0-ia32:printing-4.0-noarch
Distributor ID: RedHatEnterpriseServer
Description:    Red Hat Enterprise Linux Server release 5.9 (Tikanga)
Release:    5.9
Codename:   Tikanga
S
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000048>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.006036>
read(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000192>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.004996>
read(234, "S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%0%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%0%pre%%pre%"..., 256) = 256 <0.000076>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.000022>
read(234, "%pre%%pre%%pre%12%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%2%pre%%pre%%pre%%pre%%pre%1%pre%%pre%"..., 640) = 640 <0.000337>
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000096>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.004102>
read(234, "S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%!%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%!%pre%%pre%"..., 256) = 256 <0.000037>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.000157>
read(234, "%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%\t%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 289) = 289 <0.000047>
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000036>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.001882>
%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000048>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.006036>
read(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000192>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.004996>
read(234, "S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%0%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%0%pre%%pre%"..., 256) = 256 <0.000076>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.000022>
read(234, "%pre%%pre%%pre%12%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%2%pre%%pre%%pre%%pre%%pre%1%pre%%pre%"..., 640) = 640 <0.000337>
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000096>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.004102>
read(234, "S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%!%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%!%pre%%pre%"..., 256) = 256 <0.000037>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.000157>
read(234, "%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%\t%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 289) = 289 <0.000047>
write(234, "%pre%S%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%%pre%"..., 256) = 256 <0.000036>
poll([{fd=234, events=POLLIN}], 1, -1)  = 1 ([{fd=234, revents=POLLIN}]) <0.001882>

Discussão

Mesmo que a biblioteca ACE tenha uma opção para usá-la, provavelmente haverá pouco benefício em mudar para epoll() porque poll() está sendo chamado apenas com um descritor de arquivo nesse caso.

À medida que o sistema é carregado com 600 threads ímpares, essa chamada poll() está consumindo cerca de 98% do tempo de CPU da chamada do sistema do processo envolvido. Então, estou procurando maneiras de tornar isso mais eficiente. Parece, no entanto, que chamar poll() após um write() é o problema, pois é consistentemente na ordem de 100x mais lenta do que após uma chamada read() .

    

Answer 1

A diferença entre o tempo entre um syscall e outro é simplesmente a diferença de tempo entre o precedente e o próximo. É simplesmente um registro de data e hora da finalidade da medição, para que os usuários saibam quanto tempo um syscall leva após o outro e para descobrir se o aplicativo está pendurado em um syscall específico.

No entanto, estou um pouco confuso ao ver que as leituras são mais rápidas aqui. Simplesmente porque as gravações são frequentemente assíncronas, mas as leituras tendem a estar em linha reta e, se estivermos pulando em diferentes blocos do sistema de arquivos, a busca por disco pode torná-lo lento. Mas veja o revents (eventos solicitados - terceiro argumento na chamada poll ()) está dizendo POLLIN significando dados para serem lidos. Talvez isso possa explicar a aparente lentidão. Ainda assim, vou precisar de toda a extensão para ter certeza.

    

Answer 2

Acredito que posso estar com problemas para acreditar no que o strace me diz. Observando o código-fonte de strace , podemos ver que quando a chamada do sistema está prestes a ser inserida, a hora atual é capturada , e a hora atual é capturada quando a chamada do sistema é encerrada.

Em outras palavras, o strace está medindo o tempo do wallclock entre a entrada e a saída da chamada do sistema. O que significa que não é medir quanto tempo de CPU foi consumido pela chamada do sistema. O bloqueio de chamadas, então, pode parecer consumir a maior parte do tempo do sistema pelo aplicativo - no entanto, este é o tempo do wallclock e não tem correlação com a quantidade de CPU do sistema usada.