Regrouper les slow logs de PHP-FPM pour trouver ce que votre site attend

« Le site est lent » n'est pas quelque chose que l'on peut corriger. « Quatre requêtes lentes sur dix attendent un seul appel d'API externe », si. PHP-FPM peut vous donner la seconde phrase gratuitement, grâce à un log que la plupart des serveurs ont désactivé. Voici comment l'activer, le lire, et le regrouper pour que la réponse tombe d'elle-même.

Le problème : lent, mais où ?

Quand les pages PHP sont lentes, la plupart des enquêtes commencent de l'extérieur (outils de chronométrage de page) ou de la base de données (slow query log). Les deux sont utiles, et les deux ratent la cause la plus fréquente sur les sites modernes : PHP qui attend quelque chose qui n'est ni le CPU ni la base de données locale. Une passerelle de paiement. Une API de stock ou d'ERP. Une vérification de licence. Un verrou de session tenu par une autre requête du même visiteur. Ces attentes n'apparaissent pas en CPU, donc le serveur semble inactif pendant que les visiteurs regardent un spinner.

Le slow log de PHP-FPM les attrape toutes, parce qu'il ne se soucie pas de la raison pour laquelle une requête est lente. Il prend simplement un instantané de ce que fait la requête.

Activez-le

Dans la configuration du pool (par exemple /etc/php-fpm.d/www.conf) :

slowlog = /var/log/php-fpm/www-slow.log
request_slowlog_timeout = 3s
request_terminate_timeout = 60s

Quand une requête tourne plus longtemps que request_slowlog_timeout, le master FPM prend une backtrace du worker et l'écrit dans le slow log. La requête continue. Rien n'est tué. request_terminate_timeout est un filet de sécurité distinct qui, lui, met fin aux requêtes emballées, et il vaut la peine de le régler pendant que vous y êtes.

Choisissez un seuil juste au-dessus de ce qui paraît « normal » pour vos pages non mises en cache. Trop bas, et vous journalisez des requêtes saines. Trop haut, et vous ne voyez que les désastres. Rechargez FPM et laissez-le collecter pendant une période chargée.

Lisez une entrée

Une entrée de slow log ressemble à ceci :

[22-Oct-2026 10:14:07]  [pool www] pid 41822
script_filename = /var/www/shop/index.php
[0x00007f1c2a614f20] curl_exec() /var/www/shop/modules/erpsync/Client.php:188
[0x00007f1c2a614e10] request() /var/www/shop/modules/erpsync/Client.php:97
[0x00007f1c2a614d00] getStock() /var/www/shop/modules/erpsync/Stock.php:42
[0x00007f1c2a614bf0] hookDisplayProduct() /var/www/shop/classes/Hook.php:1017
...
[0x00007f1c2a6140a0] dispatch() /var/www/shop/index.php:28

La frame du haut, celle juste sous script_filename, est ce sur quoi la requête était bloquée au moment de l'instantané. En dessous, la façon dont elle y est arrivée. Dans cet exemple, une page produit attend curl_exec(), appelé par un module de synchronisation de stock, pendant l'affichage du produit.

Une entrée est une anecdote. Une journée d'entrées est un profil.

Regroupez par frame bloquante

Regroupez chaque entrée par sa frame du haut et comptez :

awk '/^script_filename/ { w = 1; next }
     w && /^\[0x/ {
       fn = $2
       match($0, /[^ ]+:[0-9]+$/)
       print fn " @ " substr($0, RSTART, RLENGTH)
       w = 0
     }' /var/log/php-fpm/www-slow.log \
  | sort | uniq -c | sort -rn | head -25

La sortie est une liste classée de ce que faisaient réellement les requêtes lentes. Sur une boutique lente typique, elle peut ressembler à ceci :

 812 curl_exec() @ .../modules/erpsync/Client.php:188
 497 execute() @ .../classes/db/DbPDO.php:132
 251 session_start() @ .../config/bootstrap.php:61
  88 file_get_contents() @ .../themes/shop/fonts.php:12

Puis regroupez d'une seconde façon, par la première frame située dans un répertoire de plugin, de module ou de thème. Cela transforme la liste de « quelle fonction » en « le code de qui », et c'est la question que poseront les développeurs.

Ce que signifient les frames courantes

• curl_exec(), file_get_contents() sur une URL, fsockopen() : un appel externe fait de façon synchrone pendant la génération de la page. Regardez le timeout qu'il utilise. Un long timeout vers un tiers lent immobilise un worker tout ce temps. Le remède est un timeout court, la mise en cache de la réponse, ou le déplacement de l'appel hors de la requête de page.
• execute(), query(), mysqli_query() : une attente de base de données. Prenez le fichier et la ligne vers le slow query log et faites un EXPLAIN de la requête qui s'y exécute. Si le buffer pool répond depuis la mémoire et que la requête prend toujours des secondes, le problème est la requête ou ses index, pas le matériel.
• session_start() : presque toujours un verrouillage de session. Les handlers de session sur fichiers et certains en base de données verrouillent la session pour toute la requête, donc un visiteur dont le navigateur lance plusieurs requêtes à la fois les voit faire la queue les unes derrière les autres. Fermez la session tôt avec session_write_close() dès que le code a ce qu'il lui faut, ou utilisez un handler non bloquant.
• sleep(), usleep(), boucles de réessai : le code de quelqu'un attend délibérément. En général un réessai vers un service externe qui passe une mauvaise journée.
• Des fonctions PHP pures au fond d'un template ou d'une boucle : du vrai travail CPU. Plus rare que la plupart des gens ne le pensent, et la seule catégorie où un matériel plus rapide aide directement.

Pondérez, puis confirmez le pool

Le slow log compte les requêtes au-dessus du seuil. Il ne vous dit pas combien de temps total coûte chaque catégorie. Combinez-le avec l'access log de votre serveur web, en journalisant $request_time et $upstream_response_time dans nginx, pour pondérer les requêtes lentes par URL et par durée. Une catégorie avec moins d'entrées mais des requêtes bien plus longues peut compter davantage.

Vérifiez ensuite si les requêtes lentes affament aussi le pool :

grep -c 'reached pm.max_children' /var/log/php-fpm/error.log
curl -s 'http://localhost/fpm-status?full' | head -20

Si les workers sont épuisés, les visiteurs font la queue même pour des pages qui sont rapides en elles-mêmes. Augmenter pm.max_children traite le symptôme. Raccourcir l'appel externe lent traite la cause.

Un mot sur la surcharge

Prendre une backtrace signifie que le master FPM s'attache brièvement au worker. À un seuil raisonnable, la surcharge est négligeable, parce qu'elle ne concerne que des requêtes déjà lentes. Ne réglez pas le seuil à une fraction de seconde sur un site chargé pour l'y laisser. Collectez, analysez, puis remontez-le à un niveau de surveillance.

Votre liste de contrôle

• slowlog, request_slowlog_timeout et request_terminate_timeout définis dans chaque pool.
• Une journée de slow log regroupée par frame bloquante, puis par plugin ou module.
• Les appels externes repérés et leurs timeouts lus.
• Les frames de base de données remontées jusqu'aux requêtes de ces lignes, avec EXPLAIN.
• Les entrées session_start() vérifiées pour le verrouillage de session.
• Les requêtes lentes pondérées par durée depuis l'access log, et l'épuisement du pool confirmé ou écarté.

Quand un slow log pointe quelque part où vous ne pouvez pas facilement le suivre, nous vous aiderons volontiers à le lire.

Parler à un ingénieur

Related

Voir aussi : Audits de performance d'applications web · Mises à niveau PHP et correctifs de sécurité à l'échelle du parc · Tiers web haute disponibilité, N+1 à chaque couche