Explication du php slowlog

Cet article a été publié il y a 6 ans 10 mois 4 jours, il est donc possible qu’il ne soit plus à jour. Les informations proposées sont donc peut-être expirées.

J’ai déjà abordé certaines méthodes de furieux pour analyser des problèmes avec PHP, notamment personnels avec ce blog suite à mon passage sur PHP 7. Un autre cas qu’on évoque rarement, c’est quand l’exécution est simplement trop lente. MySQL et MariaDB ont leur « slowlog » (journal lent, haha), PHP et surtout FPM propose également ce mécanisme pour nous permettre de mieux cerner le problème. Petite explication.

Je n’ai pas souvent l’occasion d’y jeter un œil, mais c’est une donnée pratique pour identifier un problème. Ce journal est en fait généré par FPM lorsqu’un appel à un script prend plus de temps, le seuil étant géré par un paramètre de configuration au niveau du pool. On récupère alors une « stacktrace », c’est à dire le cheminement de fonctions qui ont amené le script où il en est.

Le journal s’active dans le fichier de configuration de votre pool. Par exemple, pour le mien, sous Debian 8 donc avec les paquets PHP7 de Dotdeb  (/etc/php/7.0/fpm/pool.d/web1-blog.seboss666.info.conf) :

Dans l’exemple, j’ai pris une valeur de 60 secondes, mais vous pouvez choisir de bourrer une valeur plus faible, un client m’a sorti une valeur de 2 secondes, c’est à déterminer en fonction de la quantité d’information et du niveau de performances que vous cherchez à atteindre. Vous serez peut-être même amené à modifier plusieurs fois cette valeur pendant une investigation.

Le résultat aura la forme suivante :

La première ligne indique évidemment le script en cause dans l’enregistrement de la trace. La suite de la stack se lit à l’envers : de bas en haut, on décrit la série des fonctions qui ont abouti à la lenteur, la dernière (et donc la première affichée), étant généralement la fautive. En l’occurrence, ici c’est un curl_exec() qui semble être problématique. A tel point que le pool FPM est finalement tellement occupé qu’il ne pouvait plus traiter de nouvelles demandes. Et on indique la ligne à laquelle le curl_exec() en question est appelé, ce qui permet éventuellement d’identifier la destination dudit curl, et donc d’analyser plus finement pourquoi il échoue ou est trop lent (webservice surchargé, ou qui limite à un certain nombre de connexions/requêtes dans le temps). Ça peut également pointer un problème de paramétrage de la fonction, je pense notamment à un timeout qui manquerait ou qui serait trop long, laissant empiler les appels qui attendent une réponse qui n’arrive jamais; je pourrais vous raconter l’histoire d’un client qui avait ce problème à cause d’une Google Mini vieillissante et parfois plantogène. Pour les plus courageux, histoire de pas morceler l’article, je vous raconte l’histoire de cette machine à la fin de l’article.

Les sources de ralentissement peuvent être variées, les plus courantes étant probablement le cas évoqué plus haut ou une lenteur au niveau de la base de données. Très récemment, un client qui passe bientôt en production a vu son test de montée en charge décevant, le slowlog m’a permis de déterminer un goulet d’étranglement sur une génération de PDF (un appel externe à wkhtmltopdf pour être exact). J’apprends qu’au final, la page s’appelle elle-même pour envoyer son rendu à wkhtmltopdf (ce qui finalement prend plusieurs secondes). Avec 80 utilisateurs simultanés, même sur 6 vCPU, les performances s’écroulent, sans il peut encaisser 500 utilisateurs. Il est donc prévu que le client revoit son workflow pour réduire ce goulet.

Bref, un outil de plus à vous garder sous le coude pour vos investigations 😉

PS : Je vous raconte la Google Mini ?

Pour son site grand public, un client utilise une Google Mini pour son moteur de recherche. La Google Mini, où Google Search Appliance, est un matériel vendu à une époque par Google qui embarquait ses algorithmes et était chargé d’indexer un site en particulier (ou plusieurs, bref, c’était votre mini Google, d’où son nom). Cette machine est proche de la boîte noire, le snmp est vraiment ridicule (en gros les différentes sondes remontent « OK, attention, cassé »), pas de ssh, et donc il arrive parfois, surtout arrivé à un certain âge, que la boiboite soit capricieuse.

Dans ce cas, deux niveaux généralement : la boîte accepte encore des connexions mais n’y répond pas, et c’est la situation que j’explique au-dessus : le pool se remplit de requêtes en attente qui n’aboutissent pas. Sauf que le moteur de recherche du site est une de ses principales fonctions. Dans le deuxième cas on est plus tranquille parce que tout simplement ça n’accepte plus les connexions, et là la réponse est immédiate : 0 résultat. Mais là ça se complique. La GSA est un appareil qu’on installe en Datacenter, et donc qu’on s’attend à pouvoir administrer  à distance sous une forme ou une autre. Mais point D’IPMI (Intelligent Platform Management Interface), de KVM (Keyboard Video Mouse), ni d’alimentation contrôlable. Pire, impossible d’utiliser un PDU (Power Distribution Unit), à savoir une prise contrôlable à distance pour simuler un débranchement /rebranchement de prise. Mais, la GSA n’est pas prévue pour redémarrer seule, il faut l’intervention d’un humain pour appuyer sur le bouton. On comprend mieux pourquoi ils n’en ont pas beaucoup vendu et qu’ils ont arrêtés les frais.