Les performances d'Apache se dégradent considérablement au-dessus de ~ 256 demandes simultanées

J'exécute un site à faible trafic qui connaît une forte augmentation du nombre de visiteurs une fois par semaine après une mise à jour du site. Au cours de cette pointe, les performances du site sont extrêmement médiocres par rapport au reste de la semaine. La charge réelle sur les serveurs reste très faible, de manière fiable sous 10% de CPU et sous 30% de RAM (le matériel devrait être excessif pour ce que nous faisons réellement), mais pour une raison quelconque, Apache semble incapable de faire face à la quantité des demandes. Nous exécutons apache 2.2.3 sur RHEL 5.7, noyau 2.6.18-274.7.1.el5, x86_64.

En tentant de reproduire ce comportement pendant les heures creuses avec ab, je constate une baisse importante des performances lorsque vous dépassez environ 256 utilisateurs. Exécuter le test avec le plus petit cas d'utilisation possible (fichier texte statique en cours de récupération, 223 octets au total) les performances sont toujours normales avec 245 demandes simultanées:

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)

Mais dès que je clique jusqu'à 265 demandes simultanées, un sous-ensemble d'entre elles commence à prendre un temps absurde pour terminer:

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)

Ces résultats sont très cohérents sur plusieurs exécutions. Puisqu'il y a d'autres trafics vers cette case, je ne sais pas exactement où serait la coupure, s'il y en a une, mais elle semble être étrangement proche de 256.

Naturellement, j'ai supposé que cela était dû à la limite de threads dans la préfork, alors j'ai continué et ajusté la configuration pour doubler le nombre de threads disponibles et pour empêcher le pool de threads de croître et de se rétrécir inutilement:

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

mod_status confirme que je suis en cours d'exécution avec 512 threads disponibles

8 requests currently being processed, 504 idle workers

Cependant, la tentative de 265 demandes simultanées donne toujours des résultats presque identiques à ceux d'avant

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)

Après avoir parcouru la documentation (et Stack Exchange), je suis à court de paramètres de configuration supplémentaires pour tenter de résoudre ce goulot d'étranglement. Y a-t-il quelque chose qui me manque? Dois-je commencer à chercher des réponses en dehors d'Apache? Quelqu'un d'autre a-t-il vu ce comportement? Toute aide serait grandement appréciée.

ÉDITER:

Selon les conseils de Ladadadada, j'ai couru contre Apache. J'ai essayé plusieurs fois avec -tt et -T et je n'ai rien trouvé d'extraordinaire. J'ai ensuite essayé d'exécuter strace -c sur tous les processus Apache en cours d'exécution, et j'ai obtenu ceci:

% 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

(... abrégé)

Si je lis bien (et soyez indulgent, car je n'utilise pas souvent Strace), aucun des appels système ne peut expliquer le temps que prennent ces demandes. Il semble que le goulot d'étranglement se produit avant même que les demandes ne parviennent aux threads de travail.

EDIT 2:

Comme plusieurs personnes l'ont suggéré, j'ai relancé le test sur le serveur Web lui-même (auparavant, le test était exécuté à partir d'un emplacement Internet neutre). Les résultats ont été surprenants:

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)

Le temps de résultat est similaire au test basé sur Internet, mais semble être un peu moins bon lorsqu'il est exécuté localement. Plus intéressant, le profil a radicalement changé. Alors qu'auparavant la majeure partie du temps des demandes de longue durée était consacrée à la "connexion", le goulot d'étranglement semble être en cours de traitement ou en attente. Je pense que cela peut en fait être un problème distinct qui était auparavant masqué par les limitations du réseau.

En exécutant à nouveau le test à partir d'une autre machine sur le même réseau local que l'hôte Apache, je vois des résultats beaucoup plus raisonnables:

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)

Ensemble, ces deux tests soulèvent un certain nombre de questions, mais séparément de cela, il y a maintenant un argument convaincant à faire pour une sorte de goulot d'étranglement sévère du réseau se produisant sous une certaine quantité de charge. Je pense que les prochaines étapes étudieront séparément la couche réseau.

Ce que je ferais dans cette situation est exécuté

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

sur l'un de vos processus Apache pendant le test ab jusqu'à ce que vous capturiez l'une des réponses lentes. Ensuite, jetez un œil trace.txt.

Les options -ttet -Tvous donnent des horodatages du début et de la durée de chaque appel système pour aider à identifier les plus lents.

Vous pouvez trouver un seul appel système lent tel que open()ou stat()ou vous pouvez trouver un appel rapide avec (éventuellement plusieurs) poll()appels directement après. Si vous en trouvez un qui fonctionne sur un fichier ou une connexion réseau (très probablement), regardez en arrière dans la trace jusqu'à ce que vous trouviez ce fichier ou cette poignée de connexion. Les appels précédents sur cette même poignée devraient vous donner une idée de ce que l' poll()attendait.

Bonne idée en regardant l' -coption. Vous êtes-vous assuré que l'enfant Apache que vous traçiez a répondu à au moins une des requêtes lentes pendant cette période? (Je ne sais même pas comment vous feriez cela en dehors de courir stracesimultanément sur tous les enfants.)

Malheureusement, stracecela ne nous donne pas une image complète de ce que fait un programme en cours d'exécution. Il ne suit que les appels système. Beaucoup de choses peuvent se produire dans un programme qui ne nécessite rien de demander au noyau. Pour savoir si cela se produit, vous pouvez regarder les horodatages du début de chaque appel système. Si vous voyez des lacunes importantes, c'est là que le temps passe. Ce n'est pas facile à saisir et il y a toujours de petits écarts entre les appels système.

Puisque vous avez dit que l'utilisation du processeur reste faible, ce n'est probablement pas des choses excessives qui se produisent entre les appels système, mais cela vaut la peine d'être vérifié.

En examinant de plus près la sortie de ab:

Le saut soudain des temps de réponse (il semble qu'il n'y ait aucun temps de réponse entre 150 ms et 3000 ms) suggère qu'un délai d'attente spécifique se produit quelque part qui est déclenché au-dessus d'environ 256 connexions simultanées. Une dégradation plus douce serait attendue si vous manquiez de RAM ou de cycles CPU normaux IO.

Deuxièmement, la abréponse lente montre que les 3000 ms ont été dépensés dans la connectphase. Presque tous ont pris environ 30 ms, mais 5% ont pris 3 000 ms. Cela suggère que le réseau est le problème.

D'où fuyez-vous ab? Pouvez-vous l'essayer à partir du même réseau que la machine Apache?

Pour plus de données, essayez d'exécuter tcpdumpaux deux extrémités de la connexion (de préférence avec l' ntpexécution aux deux extrémités afin de pouvoir synchroniser les deux captures vers le haut.) Et recherchez les retransmissions TCP. Wireshark est particulièrement bon pour analyser les décharges car il met en évidence les retransmissions TCP dans une couleur différente, ce qui les rend faciles à trouver.

Il peut également être utile de consulter les journaux de tous les périphériques réseau auxquels vous avez accès. J'ai récemment rencontré un problème avec l'un de nos pare-feu où il pouvait gérer la bande passante en kb / s mais il ne pouvait pas gérer le nombre de paquets par seconde qu'il recevait. Il a dépassé 140 000 paquets par seconde. Quelques calculs rapides sur votre abcourse me portent à croire que vous auriez vu environ 13 000 paquets par seconde (en ignorant les 5% de demandes lentes). C'est peut-être le goulot d'étranglement que vous avez atteint. Le fait que cela se produise vers 256 pourrait être une pure coïncidence.