O desempenho do Apache degrada drasticamente acima de ~ 256 solicitações simultâneas

Question

Estou executando um site de tráfego relativamente baixo que experimenta um grande pico de visitantes uma vez por semana após a atualização do site. Durante esse pico, o desempenho do site é extremamente baixo comparado ao resto da semana. A carga real nos servidores permanece muito baixa, confiavelmente abaixo de 10% da CPU e abaixo de 30% da RAM (o hardware deve ser um completo exagero para o que estamos realmente fazendo), mas por algum motivo o Apache parece ser incapaz de lidar com a quantidade de pedidos. Estamos executando o apache 2.2.3 no RHEL 5.7, kernel 2.6.18-274.7.1.el5, x86_64.

Tentando reproduzir esse comportamento durante as horas de folga com ab, estou descobrindo uma grande queda no desempenho quando excedemos aproximadamente 256 usuários. Executar o teste com o menor caso de uso possível que eu poderia gerar (o arquivo de texto estático sendo recuperado, 223 bytes no total) o desempenho é consistentemente normal com 245 solicitações simultâneas:

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       15   25   5.8     24      37
Processing:    15   65  22.9     76      96
Waiting:       15   64  23.0     76      96
Total:         30   90  27.4    100     125

Percentage of the requests served within a certain time (ms)
  50%    100
  66%    108
  75%    111
  80%    113
  90%    118
  95%    120
  98%    122
  99%    123
 100%    125 (longest request)

Mas, assim que eu clico em 265 solicitações simultâneas, um subconjunto deles começa a demorar um tempo absurdo para concluir:

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       13  195 692.6     26    3028
Processing:    15   65  21.3     72     100
Waiting:       15   65  21.3     71      99
Total:         32  260 681.7    101    3058

Percentage of the requests served within a certain time (ms)
  50%    101
  66%    108
  75%    112
  80%    116
  90%    121
  95%   3028
  98%   3040
  99%   3044
 100%   3058 (longest request)

Esses resultados são muito consistentes em várias execuções. Como há outro tráfego indo para essa caixa, eu não tenho certeza exatamente onde seria o corte de disco rígido, se houver, mas parece ser suspeito perto de 256.

Naturalmente, presumi que isso estava sendo causado pelo limite de encadeamento no prefork, então fui em frente e ajustei a configuração para dobrar o número de encadeamentos disponíveis e evitar que o conjunto de encadeamentos aumentasse e diminuísse desnecessariamente:

<IfModule prefork.c>
StartServers     512
MinSpareServers  512
MaxSpareServers  512
ServerLimit      512
MaxClients       512
MaxRequestsPerChild  5000
</IfModule>

mod_status confirma que agora estou executando com 512 threads disponíveis

8 requests currently being processed, 504 idle workers

No entanto, a tentativa de 265 solicitações simultâneas ainda produz resultados quase idênticos aos anteriores

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:       25  211 714.7     31    3034
Processing:    17   94  28.6    103     138
Waiting:       17   93  28.5    103     138
Total:         57  306 700.8    138    3071

Percentage of the requests served within a certain time (ms)
  50%    138
  66%    145
  75%    150
  80%    161
  90%    167
  95%   3066
  98%   3068
  99%   3068
 100%   3071 (longest request)

Após vasculhar a documentação (e o Stack Exchange), estou com perda de configurações adicionais para tentar resolver esse gargalo. Existe algo que eu estou sentindo falta? Devo começar a procurar respostas fora do apache? Alguém já viu esse comportamento? Qualquer ajuda seria muito apreciada.

EDITAR:

De acordo com o conselho de Ladadadada, corri contra o apache. Eu tentei com -tt e -T algumas vezes e não consegui encontrar nada fora do comum. Então, tentei executar o strace -c em todos os processos atualmente em execução do apache e consegui isto:

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 22.09    0.317836           5     62128      4833 open
 19.91    0.286388           4     65374      1896 lstat
 13.06    0.187854           0    407433           pread
 10.70    0.153862           6     27076           semop
  7.88    0.113343           3     38598           poll
  6.86    0.098694           1    100954     14380 read

(... abdridged)

Se eu estiver lendo isso corretamente (e tenha paciência comigo, já que não uso strace com muita frequência) nenhuma das chamadas do sistema pode explicar a quantidade de tempo que essas solicitações estão sendo feitas. Quase parece que o gargalo está ocorrendo antes mesmo de os pedidos chegarem aos threads de trabalho.

EDIT 2:

Como várias pessoas sugeriram, executei o teste novamente no próprio servidor da Web (anteriormente, o teste era executado em um local neutro da Internet). Os resultados foram surpreendentes:

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0   11   6.6     12      21
Processing:     5  247 971.0     10    4204
Waiting:        3  245 971.3      7    4204
Total:         16  259 973.3     21    4225

Percentage of the requests served within a certain time (ms)
  50%     21
  66%     23
  75%     24
  80%     24
  90%     26
  95%   4225
  98%   4225
  99%   4225
 100%   4225 (longest request)

O tempo da linha de fundo é semelhante ao teste baseado na Internet, mas parece ser consistentemente um pouco pior quando executado localmente. Mais interessante, o perfil mudou drasticamente. Considerando que, antes que a maior parte do tempo dos pedidos de longa duração fosse gasto em "conectar", agora o gargalo parece estar no processamento ou na espera. Eu sou deixado para suspeitar que isso pode realmente ser um problema separado que anteriormente estava sendo mascarado por limitações de rede.

Executando o teste novamente a partir de outra máquina na mesma rede local que o host do Apache, estou vendo resultados muito mais razoáveis:

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        1    2   0.8      2       4
Processing:    13  118  99.8    205     222
Waiting:       13  118  99.7    204     222
Total:         15  121  99.7    207     225

Percentage of the requests served within a certain time (ms)
  50%    207
  66%    219
  75%    220
  80%    221
  90%    222
  95%    224
  98%    224
  99%    225
 100%    225 (longest request)

Esses dois testes juntos levantam uma série de questões, mas separadamente disso, agora há um caso convincente a ser feito para algum tipo de gargalo de rede grave que ocorre sob uma certa carga. Acho que os próximos passos investigarão a camada de rede separadamente.

    

Answer 1

O que eu faria nessa situação é executar

strace -f -p <PID> -tt -T -s 500 -o trace.txt

em um de seus processos do Apache durante o teste ab até capturar uma das respostas lentas. Então dê uma olhada em trace.txt .

As opções -tt e -T fornecem registros de data e hora do início e da duração de cada chamada do sistema para ajudar a identificar as lentas.

Você pode encontrar uma única chamada de sistema lenta, como open() ou stat() , ou pode encontrar uma chamada rápida com (possivelmente vários) poll() chamadas diretamente após ela. Se você encontrar um que esteja operando em um arquivo ou conexão de rede (muito provavelmente), olhe para trás no rastreio até encontrar esse arquivo ou identificador de conexão. As chamadas anteriores no mesmo identificador devem dar uma ideia do que o poll() estava esperando.

Boa ideia olhando para a opção -c . Você se certificou de que o filho do Apache que estava rastreando atendia pelo menos uma das solicitações lentas durante esse período? (Eu nem sei como você faria isso além de executar strace simultaneamente em todas as crianças.)

Infelizmente, strace não nos fornece a visão completa do que um programa em execução está fazendo. Apenas rastreia as chamadas do sistema. Muita coisa pode acontecer dentro de um programa que não requer pedir nada ao kernel. Para descobrir se isso está acontecendo, você pode ver os timestamps do início de cada chamada do sistema. Se você ver lacunas significativas, é aí que o tempo está indo. Isso não é facilmente aceitável e sempre há pequenas lacunas entre as chamadas do sistema.

Desde que você disse que o uso da CPU permanece baixo, provavelmente não há coisas excessivas acontecendo entre as chamadas do sistema, mas vale a pena verificar.

Olhando mais de perto a saída de ab :

O salto repentino nos tempos de resposta (parece que não há tempos de resposta entre 150ms e 3000ms) sugere que há um tempo limite específico acontecendo em algum lugar que é acionado acima de 256 conexões simultâneas. Uma degradação mais suave seria esperada se você estivesse ficando sem memória RAM ou ciclos normais de I / O.

Em segundo lugar, a resposta ab lenta mostra que os 3000ms foram gastos na fase connect . Quase todos eles levaram cerca de 30ms, mas 5% levaram 3000ms. Isso sugere que a rede é o problema.

Onde você está executando ab ? Você pode experimentá-lo na mesma rede que a máquina Apache?

Para mais dados, tente executar tcpdump em ambas as extremidades da conexão (preferencialmente com ntp em execução nas duas extremidades para que você possa sincronizar as duas capturas) e procure por quaisquer retransmissões tcp. O Wireshark é particularmente bom para analisar os despejos porque destaca as retransmissões de tcp em uma cor diferente, tornando-as fáceis de encontrar.

Também pode valer a pena examinar os registros de todos os dispositivos de rede aos quais você tem acesso. Recentemente, tive um problema com um de nossos firewalls, onde ele podia lidar com a largura de banda em termos de kb / s, mas não conseguia lidar com o número de pacotes por segundo que recebia. Chegou a 140.000 pacotes por segundo. Alguns cálculos rápidos em sua ab run me levam a acreditar que você estaria vendo cerca de 13.000 pacotes por segundo (ignorando os 5% de pedidos lentos). Talvez este seja o gargalo que você atingiu. O fato de que isso acontece em torno de 256 pode ser puramente uma coincidência.