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

Estou executando um site de tráfego relativamente baixo que apresenta um grande aumento de visitantes uma vez por semana após uma atualização do site. Durante esse pico, o desempenho do site é extremamente ruim comparado ao resto da semana. A carga real nos servidores permanece muito baixa, com confiabilidade inferior a 10% da CPU e menos de 30% de RAM (o hardware deve ser um exagero total para o que realmente estamos fazendo), mas, por alguma razão, o Apache parece não conseguir 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 horas fora com ab, estou encontrando uma grande queda no desempenho ao exceder aproximadamente 256 usuários. A execução do teste com o menor caso de uso possível que eu pude apresentar (arquivo de texto estático sendo recuperado, total de 223 bytes), o desempenho é sempre 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 rastreio até 265 solicitações simultâneas, um subconjunto delas começa a levar uma quantidade absurda de tempo 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, não tenho certeza exatamente onde estaria o corte final, se houver, mas parece suspeitamente próximo de 256.

Naturalmente, presumi que isso estava sendo causado pelo limite de encadeamentos no prefork, então fui em frente e ajustei a configuração para dobrar o número de encadeamentos disponíveis e para impedir que o conjunto de encadeamentos crescesse e encolhesse 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, tentar 265 solicitações simultâneas ainda gera resultados quase idênticos aos de antes

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)

Depois de vasculhar a documentação (e o Stack Exchange), não consigo mais configurações para tentar resolver esse gargalo. Há algo que estou perdendo? Devo começar a procurar respostas fora do apache? Alguém já viu esse comportamento? Qualquer ajuda seria muito apreciada.

EDITAR:

Seguindo o conselho de Ladadadada, corri contra o apache. Tentei com -tt e -T algumas vezes e não consegui encontrar nada fora do comum. Tentei executar strace -c em todos os processos apache atualmente em execução e obtive o seguinte:

% 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

(... encurralado)

Se eu estiver lendo isso direito (e concordar comigo, como não uso o strace com muita frequência), nenhuma das chamadas do sistema pode explicar a quantidade de tempo que essas solicitações estão demorando. Parece que o gargalo está ocorrendo antes mesmo das solicitações chegarem aos segmentos de trabalho.

EDIT 2:

Como várias pessoas sugeriram, eu 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 final é semelhante ao teste baseado na Internet, mas parece ser um pouco pior quando executado localmente. Mais interessante, o perfil mudou dramaticamente. Considerando que antes que a maior parte do tempo das solicitações de execução longa fosse gasta em "conexão", agora o gargalo parece estar em processamento ou em espera. Suspeito que esse possa realmente ser um problema separado que anteriormente estava sendo mascarado por limitações de rede.

Executando o teste novamente de outra máquina na mesma rede local que o host 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 perguntas, mas separadamente disso, agora há um argumento convincente a ser feito para algum tipo de gargalo grave na rede que ocorre sob uma certa carga. Eu acho que os próximos passos serão investigar a camada de rede separadamente.

O que eu faria nessa situação é executado

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

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

As opções -tte -Tfornecem carimbos de data e hora do início e da duração de cada chamada do sistema para ajudar a identificar os mais lentos.

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

Boa ideia olhando a -copção. Você garantiu que o filho Apache que você estava rastreando atendeu a pelo menos uma das solicitações lentas durante esse período? (Eu nem tenho certeza de como você faria isso, além de executar stracesimultaneamente todas as crianças.)

Infelizmente, stracenão nos fornece uma imagem completa do que um programa em execução está fazendo. Ele rastreia apenas as chamadas do sistema. Muita coisa pode acontecer dentro de um programa que não requer nada do kernel. Para descobrir se isso está acontecendo, você pode observar os registros de data e hora do início de cada chamada do sistema. Se você encontrar lacunas significativas, é para onde o tempo está indo. Isso não é facilmente aceitável e sempre existem pequenas lacunas entre as chamadas do sistema.

Como você disse que o uso da CPU permanece baixo, provavelmente não é algo excessivo acontecendo entre as chamadas do sistema, mas vale a pena conferir.

Observando mais atentamente 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 com ciclos da CPU IO normal.

Em segundo lugar, a abresposta lenta mostra que os 3000ms foram gastos na connectfase. Quase todos levaram cerca de 30ms, mas 5% demoraram 3000ms. Isso sugere que a rede é o problema.

De onde você está fugindo ab? Você pode experimentá-lo da mesma rede que a máquina Apache?

Para obter mais dados, tente executar tcpdumpnas duas extremidades da conexão (de preferência com a ntpexecução nas duas extremidades, para sincronizar as duas capturas.) E procure por retransmissões tcp. O Wireshark é particularmente bom para analisar os despejos, pois destaca as retransmissões tcp em uma cor diferente, facilitando sua localização.

Também pode valer a pena examinar os logs de todos os dispositivos de rede aos quais você tem acesso. Recentemente, tive um problema com um de nossos firewalls, em que 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 estava recebendo. Chegou a 140.000 pacotes por segundo. Alguns cálculos rápidos em sua abexecução me levam a acreditar que você estaria vendo cerca de 13.000 pacotes por segundo (ignorando os 5% de solicitações lentas). Talvez este seja o gargalo que você alcançou. O fato de isso acontecer por volta de 256 pode ser pura coincidência.