Descubre cuánto tarda en ejecutar tu script PHP

Para que una aplicación web o de escritorio sea satisfactoria, no basta solamente con que cumpla con los requerimientos de diseño, debe hacerlo de forma eficiente en cuanto al consumo de recursos y de tiempo, cosas que muchas veces están vinculadas, muy vinculadas.

Una aplicación web con alto consumo de recursos puede redundar en costos adicionales para el proveedor del servicio, por ejemplo, pagando un mayor precio por uso adicional de CPU en servidores bajo demanda del tipo Amazon AWS o Microsoft Azure. Por otra parte, el tiempo medio de carga de una página web es de 2,5 segundos en computadores de escritorio y de 8,6 segundos en dispositivos móviles (de acuerdo a un estudio publicado en tooltester.com), de forma que una página que tarde más que eso aumenta el riesgo que el usuario se lleve una experiencia poco satisfactoria y pueda conducirlo a abandonar la consulta o en el peor de los casos, a cambiar su proveedor del servicio. Es muy posible que al dedicar un poco de tiempo y esfuerzo a mejorar los tiempos de respuesta de una aplicación, consigamos a su vez optimizar el uso de recursos. Pero que mejor forma de visualizarlo que con un ejemplo de la vida real.

Unas semanas atrás estuve revisando una aplicación web que desarrollé en PHP y uno de sus módulos debía revisar los archivos de múltiples directorios para presentar en pantalla información de interés sobre su contenido. Al probarla en mi computador, encontré que tardaba entre 5 y 7 segundos en generar la página de respuesta, un tiempo que como se mencionó antes, es demasiado alto para los estándares esperados, especialmente cuando tenemos en cuenta que estaba probando la aplicación en mi equipo local y no en un servidor en Internet, donde habría que sumar algunos segundos extra por cuenta del tiempo que toman las consultas en recorrer la distancia desde tu equipo hasta el lugar donde se encuentre el servidor remoto, ocupación del servidor, congestión de la red y un largo etcétera sobre el no tienes control alguno. Era claro entonces que aunque mi aplicación generaba la respuesta deseada de acuerdo a los requerimientos del cliente, no lo hacía en un tiempo aceptable. Así que me puse en la tarea de revisar el código para encontrar dónde se generaba el retraso.

Cuando estas cosas pasan, pueden ocurrir dos cosas:

• El retraso se encuentra concentrado en puntos definidos de la aplicación, o
• El retraso es causado por la suma de pequeños tiempos aceptables en diferentes bloques de código.

En el segundo caso, la sugerencia más práctica sería reestructurar la aplicación en si, nada qué hacer. Pero si tienes suerte y el problema es del primer tipo, vale la pena adoptar una postura detectivesca y rastrear esos puntos donde se concentra el retraso para así depurarlo. Pero cualquiera sea el caso, el primer paso consistirá siempre en incluir en tu script de entrada (aquel directamente invocado cuando ejecutas la aplicación web) puntos de medición entre bloques de código que en lo posible, cumplan con las siguientes características:

• Antes y después de usar una función o método que realiza múltiples tareas.
• Antes y después de usar una función o método que realiza consultas a bases de datos o fuentes externas como archivos en disco duro, servidores remotos, etc.
• Ciclos for, while o foreach que invocan múltiples funciones o que tienen muchas iteraciones.

Lo que haremos será incluir una función de rastreo de tiempo (que llamaremos timecheck()) entre estos bloques de código, algo asi como:

// Starting code block

timecheck('START');

// Code block #1

timecheck('1');

// Code block #2

timecheck('2');

// Code block #3

timecheck('3');

// Code block #4

timecheck('4');

// Closing code

timecheck('END');

En caso que el diseño de nuestra aplicación no nos permita mostrar estos mensajes directo a pantalla, una alternativa sería enviarlos directamente a un log de errores o si estamos monitoreando un bloque Javascript, enviarlos a la consola de depuración. Pero si nuestra aplicación permite que podamos visualizarlo en pantalla (una acción que agiliza la búsqueda ya que tenemos acceso directo a los datos sin recurrir a otros medios) y la tenemos implementada en PHP (como fue en mi caso), podemos usar un código como el siguiente para habilitar nuestra función de monitoreo de tiempo:

function timecheck(string $text = '') {

	$now = microtime(true);

	// Valida que se haya registrado la hora de inicio.
	// Usualmente, $_SERVER['REQUEST_TIME_FLOAT'] es declarado por el web server.
	if (!isset($_SERVER['REQUEST_TIME_FLOAT'])) {
		$_SERVER['REQUEST_TIME_FLOAT'] = $now;
	}

	// Valida si fue registrado un punto de chequeo anterior.
	if (!isset($GLOBALS['TIMETRIAL_PARTIAL_TIME'])) {
		$GLOBALS['TIMETRIAL_PARTIAL_TIME'] = $now;
	}

	// Obtiene la diferencia de tiempo actual, formateado a dos decimales.
	$partial = number_format(($now - $GLOBALS['TIMETRIAL_PARTIAL_TIME']), 3);

	// Actualiza la hora de chequeo
	$GLOBALS['TIMETRIAL_PARTIAL_TIME'] = $now;

	// Obtiene el script y línea desde donde se invoca.
	$trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS);

	// Usa el primer elemento del arreglo $trace para obtener el origen.
	$source = str_replace($_SERVER['DOCUMENT_ROOT'] . '\\', '', $trace[0]['file']);

	// Obtiene el tiempo total transcurrido.
	$time = number_format(($now - $_SERVER['REQUEST_TIME_FLOAT']), 3);

	// Adiciona etiquetas a mostrar en pantalla (opcional)
	if ($text != '') {
		$text = "<div style=\"float:right;padding-left:5px;color:cyan\">{$text}</div>";
	}

	// Muestra el mensaje, adiciona algunos estilos.
	echo PHP_EOL . "<div style=\"font-family:Calibri;background:#000;color:#fefefe;padding:5px;margin:5px 0;font-size:14px\">" .
		"<b style=\"color:yellow\">TIME/TRIAL</b> Ellapse time: <b>{$time}</b> / Since last check-point: <b>{$partial}</b>{$text}" .
		"<div style=\"color:#ccc;font-size:12px;padding-top:3px\">{$source}:{$trace[0]['line']}</div>".
		"</div>" . PHP_EOL;
}

Al ejecutarlo, tendremos una respuesta similar a la mostrada en la siguiente imagen:

Con suerte, este primer monitoreo nos mostrará el bloque donde se presenta el mayor tiempo de consumo (en nuestro ejemplo ocurre en el bloque #3). ¿Cómo proseguimos? Si en el código no es claro qué genera el retraso porque por ejemplo, corresponde a una función o uso de clases definidas en otros archivos, procedemos a incluir puntos de medición en esos archivos y retirar aquellos que ya no necesitamos, y continuamos así hasta encontrar ese punto crítico de retraso.

Finalmente, mi búsqueda me llevó la revisión de un par de scripts adicionales al de punto de entrada de la aplicación, pero finalmente pude encontrar la causa de la demora: el sistema estaba leyendo y analizando cada vez todos los archivos, de forma que si bien el tiempo para cada uno era aceptable, el valor acumulado era demasiado alto para el estándar esperado. La solución consistió en reducir el tiempo de análisis implementando un esquema de caché (similar al comentado anteriormente en este otro artículo), de forma que los archivos solamente se lean cuando se detecte algún cambio en el tamaño o fecha de modificación de los mismos. El resultado fue una reducción significativa en el tiempo de respuesta, excepto claro para la primera consulta, cuando el caché debe crearse para todos los archivos, pero este es un retraso aceptable considerando que ocurre en un evento que no se repite con frecuencia.

Espero que te resulten de utilidad estas recomendaciones y este ejercicio de la vida real, que puedas tomar el tiempo para asegurarte que tus aplicaciones respondan en el menor tiempo posible es algo que los usuarios del servicio sin duda lo apreciarán aunque rara vez o nunca te lo agradezcan. Así es esta vida, lo mejor es hacer las cosas bien sin esperar a recibir un gracias, aunque siempre son bienvenidas.

Y gracias a ti por tu lectura. ¡Hasta una próxima!

Ilustración adaptada de una imagen de Gerd Altmann en Pixabay