Una característica muy interesante que posee el servidor Fast CGI de PHP (PHP-FPM) es la posibilidad de detectar, y registrar en un log, aquellas solicitudes que tienen un tiempo de ejecución elevado. Esto puede ser de gran utilidad para descubrir cuales son las páginas de un sitio Web que tardan demasiado tiempo en procesar en el servidor, y por ende cargan demasiado lento.



Pero lo mejor de todo es que se trata de una opción muy fácil de configurar y habilitar, y no importa qué servidor Web se esté utilizando (Apache o Nginx), pues es una configuración a nivel PHP-FPM. Más precisamente a nivel pool de PHP-FPM.

Editar el archivo de configuración del pool donde se desee habilitar el registro de scripts lentos (llamado slowlog). Por defecto, PHP-FPM incluye el pool "www" y el registro de scripts lentos se encuentra deshabilitado:

root@wheezy:~# nano /etc/php5/fpm/pool.d/www.conf

La variable slowlog indica la ruta al archivo donde se guardará el log, mientras que la variable request_slowlog_timeout indica el tiempo (por defecto segundos) a partir del cual un script PHP es considerado lento:

slowlog = /var/log/$pool.log.slow
request_slowlog_timeout = 5

Para un sitio Web simple se recomienda utilizar un valor de 5 a 10 segundos, aunque puede ser más grande para el caso de aplicaciones Web que posean scripts que realicen procesamientos complejos o de larga duración.

Cuando una solicitud alcanza el tiempo estipulado (en el ejemplo 5 segundos), se volcará la traza de ejecución de PHP en el log. Es posible modificar las unidades del valor de timeout agregando la letra m para minutos (por ejemplo "2m" para especificar 2 minutos), h para horas ("1h" para indicar 1 hora) o d para días ("2d").

A través del volcado de la traza de PHP para scripts lentos, se puede determinar fácilmente cuáles son las llamadas a funciones y scripts que tienen un tiempo de procesamiento crítico. De esta forma es posible optimizar dichas funciones/scripts para mejorar el rendimiento del sitio y bajar el tiempo de procesamiento.

Cabe destacar que, muchas veces, un script PHP puede tener un tiempo de ejecución elevado debido a que está esperando una respuesta de una consulta a una base de datos. En este caso será necesario tomar las medidas correspondientes para optimizar dichas consultas, o incluso las bases de datos y sus tablas. De todas formas, la traza PHP permitirá determinar con precisión si una demora se debe a ejecución de código PHP, acceso al sistema de archivos, o tiempo de respuesta de un motor de bases de datos.

La siguiente es una porción de un slowlog para un sitio Web real en producción. Por cuestiones de seguridad se han reemplazado algunas rutas por asteriscos:

[12-Nov-2015 11:30:49]  [pool www] pid 13485
script_filename = ***********************index.php
[0x00007f6063d120c8] fopen() ***************************************cache/********/file.php:130
[0x00007f6063d11db8] store() ***************************************cache/cache.php:237
[0x00007f6063d11928] store() ***************************************cache/controller.php:234
[0x00007f6063d10ee0] store() ***************************************document/*****/html.php:406
[0x00007f6063d10b50] getBuffer() ***************************************document/*****/html.php:697
[0x00007f6063d10968] _renderTemplate() ***************************************document/*****/html.php:477
[0x00007f6063d10040] render() *************************************************cms.php:1059
[0x00007f6063d0f8e8] render() *************************************************site.php:745
[0x00007f6063d0f590] render() *************************************************cms.php:258
[0x00007f6063d0f168] execute() ***********************index.php:45

[13-Nov-2015 00:31:37]  [pool www] pid 4336
script_filename = ***********************index.php
[0x00007f6063d123c0] fopen() ***************************************cache/********/file.php:130
[0x00007f6063d120b0] store() ***************************************cache/cache.php:237
[0x00007f6063d11c20] store() ***************************************cache/controller.php:234
[0x00007f6063d111d8] store() ***************************************document/*****/html.php:406
[0x00007f6063d10e48] getBuffer() ***************************************document/*****/html.php:697
[0x00007f6063d10c60] _renderTemplate() ***************************************document/*****/html.php:477
[0x00007f6063d10338] render() *************************************************cms.php:1059
[0x00007f6063d0fbe0] render() *************************************************site.php:745
[0x00007f6063d0f888] render() *************************************************cms.php:258
[0x00007f6063d0f460] execute() ***********************index.php:45

[13-Nov-2015 07:53:26]  [pool www] pid 17429
script_filename = ***********************index.php
[0x00007f6063d12368] fopen() ***************************************cache/********/file.php:130
[0x00007f6063d12058] store() ***************************************cache/cache.php:237
[0x00007f6063d11bc8] store() ***************************************cache/controller.php:234
[0x00007f6063d11180] store() ***************************************document/*****/html.php:406
[0x00007f6063d10df0] getBuffer() ***************************************document/*****/html.php:697
[0x00007f6063d10c08] _renderTemplate() ***************************************document/*****/html.php:477
[0x00007f6063d102e0] render() *************************************************cms.php:1059
[0x00007f6063d0fb88] render() *************************************************site.php:745
[0x00007f6063d0f830] render() *************************************************cms.php:258
[0x00007f6063d0f408] execute() ***********************index.php:45

[13-Nov-2015 10:26:54]  [pool www] pid 21995
script_filename = ***********************index.php
[0x00007f6063d11d80] mysqli_connect() ***************************************database/****/mysqli.php:164
[0x00007f6063d11bb8] connect() ***************************************database/****/mysqli.php:227
[0x00007f6063d118f8] escape() ***************************************database/****.php:1488
[0x00007f6063d113e8] quote() ***************************************session/********/database.php:40
[0x00007ffc5a4b2240] read() unknown:0
[0x00007f6063d11030] session_start() ***************************************session/******.php:665
[0x00007f6063d10d78] _start() ***************************************session/******.php:603
[0x00007f6063d101b0] start() *************************************************cms.php:739
[0x00007f6063d0fd08] loadSession() *************************************************cms.php:131
[0x00007f6063d0fba8] __construct() *************************************************site.php:63
[0x00007f6063d0f820] __construct() *************************************************cms.php:399
[0x00007f6063d0f5a0] getInstance() ***************************************factory.php:125
[0x00007f6063d0f170] getApplication() ***********************index.php:42

Se observa que las principales demoras ocurren al acceder al sistema de archivos (notar sucesivas llamadas a fopen()). Aunque también ocurren demoras al conectarse a un servidor de bases de datos MySQL (ver mysqli_connect).

Esta es otra de las importantes ventajas que se pueden aprovechar cuando se utiliza PHP en modo Fast CGI.

Para más información, revisar la página del manual de PHP: PHP Manual - Installation and Configuration - FastCGI Process Manager (FPM).


Tal vez pueda interesarte


Compartí este artículo