Agrupar los slow logs de PHP-FPM para saber qué espera su sitio

«El sitio va lento» no es algo que nadie pueda arreglar. «Cuatro de cada diez peticiones lentas están esperando a una llamada a una API externa» sí lo es. PHP-FPM puede darle la segunda frase gratis, a través de un log que la mayoría de los servidores tienen desactivado. Así se activa, se lee y se agrupa para que la respuesta salga sola.

El problema: lento, pero ¿dónde?

Cuando las páginas PHP van lentas, la mayoría de las investigaciones empiezan desde fuera (herramientas de medición de páginas) o desde la base de datos (slow query log). Ambas son útiles, y ambas pasan por alto la causa más común en los sitios modernos: PHP esperando a algo que no es ni CPU ni la base de datos local. Una pasarela de pago. Una API de stock o de ERP. Una comprobación de licencia. Un bloqueo de sesión retenido por otra petición del mismo visitante. Esas esperas no aparecen como CPU, así que el servidor parece ocioso mientras los visitantes miran un spinner.

El slow log de PHP-FPM las captura todas, porque no le importa por qué una petición es lenta. Simplemente toma una instantánea de lo que la petición está haciendo.

Actívelo

En la configuración del pool (por ejemplo /etc/php-fpm.d/www.conf):

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

Cuando una petición lleva ejecutándose más de request_slowlog_timeout, el master de FPM toma un backtrace del worker y lo escribe en el slow log. La petición continúa; no se mata nada. request_terminate_timeout es una red de seguridad separada que sí termina las peticiones desbocadas, y merece la pena fijarla ya que está ahí.

Elija un umbral justo por encima de lo que es «normal» para sus páginas sin caché. Demasiado bajo, y registrará peticiones sanas. Demasiado alto, y solo verá los desastres. Recargue FPM y déjelo recoger durante un periodo de actividad.

Lea una entrada

Una entrada del slow log tiene este aspecto:

[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

El frame superior, el que está justo debajo de script_filename, es aquello en lo que la petición estaba bloqueada en el momento de la instantánea. Debajo está cómo llegó hasta ahí. En este ejemplo, una página de producto está esperando a curl_exec(), llamado por un módulo de sincronización de stock, durante la visualización del producto.

Una entrada es una anécdota. Un día de entradas es un perfil.

Agrupe por el frame que bloquea

Agrupe cada entrada por su frame superior y cuente:

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 salida es una lista ordenada de lo que estaban haciendo realmente las peticiones lentas. En una tienda lenta típica podría tener este aspecto:

 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

Después agrupe de una segunda manera, por el primer frame dentro de un directorio de plugin, módulo o tema. Eso convierte la lista de «qué función» en «código de quién», que es la pregunta que harán los desarrolladores.

Qué significan los frames comunes

• curl_exec(), file_get_contents() sobre una URL, fsockopen(): una llamada externa hecha de forma síncrona durante la generación de la página. Mire el timeout que usa; un timeout largo contra un tercero lento detiene un worker durante todo ese tiempo. La solución es un timeout corto, cachear la respuesta, o sacar la llamada de la petición de página.
• execute(), query(), mysqli_query(): una espera de base de datos. Lleve el fichero y la línea al slow query log y haga EXPLAIN de la consulta que se ejecuta ahí. Si el buffer pool responde desde memoria y la consulta sigue tardando segundos, el problema es la consulta o sus índices, no el hardware.
• session_start(): casi siempre bloqueo de sesión. Los manejadores de sesión en fichero y algunos en base de datos bloquean la sesión durante toda la petición, de modo que un visitante cuyo navegador lanza varias peticiones a la vez las tiene en cola una detrás de otra. Cierre la sesión pronto con session_write_close() en cuanto el código tenga lo que necesita, o use un manejador no bloqueante.
• sleep(), usleep(), bucles de reintento: el código de alguien está esperando deliberadamente. Normalmente un reintento contra un servicio externo que está teniendo un mal día.
• Funciones PHP puras en lo profundo de una plantilla o un bucle: trabajo de CPU genuino. Más raro de lo que la gente espera, y el único grupo en el que un hardware más rápido ayuda directamente.

Pondérelo, y después confirme el pool

El slow log cuenta las peticiones por encima del umbral; no le dice cuánto tiempo total cuesta cada grupo. Combínelo con el access log de su servidor web, registrando $request_time y $upstream_response_time en nginx, para ponderar las peticiones lentas por URL y por duración. Un grupo con menos entradas pero peticiones mucho más largas puede importar más.

Después compruebe si las peticiones lentas también están dejando sin workers al pool:

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

Si los workers están agotados, los visitantes hacen cola incluso para páginas que por sí solas son rápidas. Subir pm.max_children trata el síntoma; acortar la llamada externa lenta trata la causa.

Una palabra sobre la sobrecarga

Tomar un backtrace significa que el master de FPM se engancha brevemente al worker. Con un umbral sensato la sobrecarga es despreciable, porque solo ocurre con peticiones que ya son lentas. No fije el umbral en una fracción de segundo en un sitio con mucho tráfico y lo deje ahí. Recoja, analice, y después súbalo de nuevo a un nivel de monitorización.

Su lista de comprobación

• slowlog, request_slowlog_timeout y request_terminate_timeout fijados en cada pool.
• Un día de slow log agrupado por frame que bloquea, y después por plugin o módulo.
• Llamadas externas localizadas y sus timeouts leídos.
• Frames de base de datos rastreados hasta las consultas de esas líneas, con EXPLAIN.
• Entradas de session_start() revisadas por bloqueo de sesión.
• Peticiones lentas ponderadas por duración a partir del access log, y agotamiento del pool confirmado o descartado.

Cuando un slow log apunta a un sitio que no puede seguir con facilidad, estaremos encantados de ayudar a leerlo.

Hable con un ingeniero

Related

Relacionado: Auditorías de rendimiento de aplicaciones web · Actualizaciones de PHP y parcheo de seguridad en toda la flota · Capas web de alta disponibilidad, N+1 en cada nivel