Raggruppare gli slow log di PHP-FPM per scoprire cosa aspetta il vostro sito

«Il sito è lento» non è qualcosa che qualcuno possa risolvere. «Quattro richieste lente su dieci stanno aspettando una chiamata a un'API esterna» sì. PHP-FPM può dirvi la seconda frase gratis, attraverso un log che la maggior parte dei server ha spento. Ecco come accenderlo, leggerlo e raggrupparlo in modo che la risposta salti fuori.

Il problema: lento, ma dove?

Quando le pagine PHP sono lente, la maggior parte delle indagini parte dall'esterno (strumenti di timing delle pagine) o dal database (slow query log). Entrambi sono utili, ed entrambi mancano la causa più comune sui siti moderni: PHP che aspetta qualcosa che non è né CPU né il database locale. Un gateway di pagamento. Un'API di magazzino o ERP. Un controllo di licenza. Un lock di sessione tenuto da un'altra richiesta dello stesso visitatore. Quelle attese non si vedono come CPU, quindi il server sembra fermo mentre i visitatori fissano una rotellina.

Lo slow log di PHP-FPM le cattura tutte, perché non gli importa perché una richiesta è lenta. Fa semplicemente un'istantanea di ciò che la richiesta sta facendo.

Accendetelo

Nella configurazione del pool (per esempio /etc/php-fpm.d/www.conf):

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

Quando una richiesta è in esecuzione da più di request_slowlog_timeout, il master FPM prende un backtrace del worker e lo scrive nello slow log. La richiesta prosegue; nulla viene terminato. request_terminate_timeout è una rete di sicurezza separata che invece termina le richieste fuori controllo, e vale la pena impostarla già che ci siete.

Scegliete una soglia appena sopra ciò che è «normale» per le vostre pagine non in cache. Troppo bassa, e loggate richieste sane. Troppo alta, e vedete solo i disastri. Ricaricate FPM e lasciatelo raccogliere per un periodo di traffico.

Leggete una voce

Una voce dello slow log si presenta così:

[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

Il frame in cima, quello direttamente sotto script_filename, è ciò su cui la richiesta era bloccata nel momento dell'istantanea. Sotto c'è come ci è arrivata. In questo esempio, una pagina prodotto sta aspettando curl_exec(), chiamata da un modulo di sincronizzazione del magazzino, durante la visualizzazione del prodotto.

Una voce è un aneddoto. Una giornata di voci è un profilo.

Raggruppate per il frame bloccante

Raggruppate ogni voce per il suo frame in cima e contate:

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

L'output è una classifica di ciò che le richieste lente stavano effettivamente facendo. Su un tipico negozio lento potrebbe essere così:

 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

Poi raggruppate in un secondo modo, per il primo frame dentro una directory di plugin, modulo o tema. Questo trasforma l'elenco da «quale funzione» a «il codice di chi», che è la domanda che gli sviluppatori faranno.

Cosa significano i frame comuni

• curl_exec(), file_get_contents() su un URL, fsockopen(): una chiamata esterna fatta in modo sincrono durante la generazione della pagina. Guardate il timeout che usa; un timeout lungo verso una terza parte lenta blocca un worker per tutto quel tempo. La soluzione è un timeout breve, mettere in cache la risposta, o spostare la chiamata fuori dalla richiesta di pagina.
• execute(), query(), mysqli_query(): un'attesa sul database. Portate file e riga allo slow query log e fate EXPLAIN della query che gira lì. Se il buffer pool risponde dalla memoria e la query impiega comunque secondi, il problema è la query o i suoi indici, non l'hardware.
• session_start(): quasi sempre il lock della sessione. I gestori di sessione su file e alcuni su database bloccano la sessione per l'intera richiesta, quindi un visitatore il cui browser lancia più richieste insieme le vede accodarsi una dietro l'altra. Chiudete presto la sessione con session_write_close() una volta che il codice ha ciò che gli serve, oppure usate un gestore non bloccante.
• sleep(), usleep(), cicli di retry: il codice di qualcuno sta aspettando di proposito. Di solito un retry verso un servizio esterno che sta passando una brutta giornata.
• Funzioni PHP pure in profondità in un template o in un ciclo: lavoro CPU vero. Più raro di quanto si pensi, e l'unico gruppo in cui hardware più veloce aiuta direttamente.

Pesatelo, poi confermate il pool

Lo slow log conta le richieste sopra la soglia; non vi dice quanto tempo totale costa ciascun gruppo. Combinatelo con l'access log del vostro web server, loggando $request_time e $upstream_response_time in nginx, per pesare le richieste lente per URL e per durata. Un gruppo con meno voci ma richieste molto più lunghe può contare di più.

Poi verificate se le richieste lente stanno anche affamando il pool:

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

Se i worker sono esauriti, i visitatori si accodano anche per pagine che da sole sono veloci. Alzare pm.max_children cura il sintomo; accorciare la chiamata esterna lenta cura la causa.

Una parola sull'overhead

Prendere un backtrace significa che il master FPM si collega brevemente al worker. A una soglia ragionevole l'overhead è trascurabile, perché accade solo a richieste che sono già lente. Non impostate la soglia a una frazione di secondo su un sito trafficato lasciandola lì. Raccogliete, analizzate, poi riportatela a un livello di monitoraggio.

La vostra checklist

• slowlog, request_slowlog_timeout e request_terminate_timeout impostati in ogni pool.
• Una giornata di slow log raggruppata per frame bloccante, poi per plugin o modulo.
• Chiamate esterne individuate e i loro timeout letti.
• Frame del database ricondotti alle query su quelle righe, con EXPLAIN.
• Voci session_start() verificate per il lock di sessione.
• Richieste lente pesate per durata dall'access log, ed esaurimento del pool confermato o escluso.

Quando uno slow log punta da qualche parte che non riuscite a seguire facilmente, siamo lieti di aiutarvi a leggerlo.

Parla con un ingegnere

Related

Correlati: Audit delle prestazioni delle applicazioni web · Aggiornamenti PHP e patching di sicurezza su tutta la flotta · Web tier ad alta disponibilità, N+1 a ogni livello