Por que o brk () na saída strace demoraria vários segundos?

Question

Temos notado uma desaceleração significativa de um dos nossos aplicativos quando migrados para o Ubuntu Hardy, amd64. Funciona perfeitamente no Debian Sarge i386.

A execução de um 'strace -r' no processo httpd (Apache 1.3) mostrou a seguinte seção problemática:

     0.000083 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "_323-412D
     0.000083 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "_323-412D%pre%%pre%%pre%00%pre%%pre%%pre%%pre%recueil-cours"..., 32727, 0, NULL, NULL) = 8192
     0.000061 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "%pre%%pre%%pre%00%pre%%pre%%pre%%pre%recueil-courses%pre%%pre%%pre%er2"..., 32767, 0, NULL, NULL) = 2369
     0.117422 brk(0x397a000)            = 0x397a000
     0.140721 brk(0x399b000)            = 0x399b000
     4.457037 brk(0x39bc000)            = 0x39bc000
     0.078792 stat("/opt/semantico/slot/nijhoff/3/sitecode/live/public_home.html", {st_mode=S_IFREG|0644, st_size=2194, ...}) = 0
%pre%%pre%00%pre%%pre%%pre%%pre%recueil-cours"..., 32727, 0, NULL, NULL) = 8192
     0.000061 poll([{fd=8, events=POLLIN|POLLERR, revents=POLLIN}], 1, -1) = 1
     0.000026 recvfrom(8, "%pre%%pre%%pre%00%pre%%pre%%pre%%pre%recueil-courses%pre%%pre%%pre%er2"..., 32767, 0, NULL, NULL) = 2369
     0.117422 brk(0x397a000)            = 0x397a000
     0.140721 brk(0x399b000)            = 0x399b000
     4.457037 brk(0x39bc000)            = 0x39bc000
     0.078792 stat("/opt/semantico/slot/nijhoff/3/sitecode/live/public_home.html", {st_mode=S_IFREG|0644, st_size=2194, ...}) = 0

Observe o brk na última, mas uma linha - sugerindo que o brk (0x399b000) levou 4,45 segundos!

Eu verifiquei a página man do brk, o que indica que ela é usada para solicitar um heap / heap de dados maior, mas não consigo encontrar nenhum motivo para que isso demore tanto.

Alguém tem alguma ideia?

    

Answer 1

Acontece que este problema foi principalmente devido ao meu mal-entendido da saída do strace -r.

A opção '-r' fornece o tempo (em segundos) desde a última chamada do sistema, não o tempo que a última chamada de sistema levou para executar.

Nesse caso, a CPU estava produzindo alguns cálculos, não processando o brk ().

O problema aqui está resolvido agora - foi causado por uma atualização para o perl 5.8.9 (do perl 5.8.8). Fizemos o backup da atualização perl e analisaremos a causa da lentidão do perl 5.8.9 mais tarde.

    

Answer 2

brk () é como o malloc expande seu conjunto de memórias disponíveis. Isso significa que o kernel pode estar trocando ou jogando jogos de shell de memória para encontrar um novo segmento de memória grande o suficiente para retornar, então o desempenho é ... imprevisível. Dito isso, você pode querer olhar para alguns dos sintetizadores de uso da memória (sysctl -a | grep ^ vm deve dar a você um bom lugar para começar a procurar) para alterar sua estratégia de alocação de memória.