Profiling en PHP: ¿qué partes consumen más?

Autor: Armonth | El viernes 31 de agosto del 2007 @ 05:22.

Hace unos días comentaba casi de pasada lo bien que iría tener una utilidad para saber qué funciones de WordPress (PHP) consumen más a lo cual el primer comentario ya comentaba que la respuesta eran herramientas de profiling para PHP.

Ayer le dediqué un rato al tema y si bien sigo viendo que sería más fácil algo integrado en WordPress hay que reconocer que hacerlo con profiling genérico tiene de ventaja que es independiente del script a revisar.

Existen varios programas para ello aunque yo sólo conozco dos: Xdebug y APD. Vamos a hablar del segundo.

APD o Advanced PHP Debugger se describe a si mismo como un completo profiler/debugger que se carga como una extensión de Zend. Está pensado para ser una alternativa a gprof en C y DPROF para Perl.

¿Cómo instalarlo?

Hay varias maneras, si usas PHP4 y Debian sólo haría falta un apt-get install php4-apd pero a mí me da dependencias rotas y además en localhost uso PHP5. Vamos a instalarlo de forma manual "relativamente"...

Lo primero es que necesita PHP como CGI, aunque eso no impide usar de normal el mod_php e instalar el CGI, también hace falta el phpize, yo tengo instalado un LAMP funcional con PHP5 y he tenido que agregar estos paquetes: php5-cgi y php-dev.

Luego he intentado instalar la extensión con pear:

pear install apd

Pero me ha soltado un error con solución incluida, hay que usar:

pecl install apd

Si todo va bien bajará la extensión y la compilará, en mi caso la ruta donde guarda la extensión es /usr/lib/php5/20060613+lfs/apd.so pero si no sabéis donde lo guarda podéis buscarlo mediante:

updatedb && locate apd.so

Ahora toca configurar el PHP5 para que cargue el módulo, creo un fichero llamado apd.ini en /etc/php5/conf.d/apd.ini_ con la siguiente configuración:

# configuration for php APD module   
zend_extension = /usr/lib/php5/20060613+lfs/apd.so   
apd.dumpdir = /var/www/apd   
apd.statement_trace = 0

La primera línea es la ruta a la extensión, la segunda donde se guardarán los "logs" y la tercera, sinceramente no estoy seguro, venía con un fichero de configuración de ejemplo.

Reiniciamos el servidor y creamos un fichero PHP con la función [phpinfo()](http://php.net/phpinfo) y podremos ver todo lo que tiene PHP, deberíamos ver algo parecido a:

Additional .ini files parsed /etc/php5/apache2/conf.d/apd.ini,

This program makes use of the Zend Scripting Language Engine: Zend Engine v2.2.0, Copyright (c) 1998-2007 Zend Technologies with Advanced PHP Debugger (APD) v0.9, , by George Schlossnagle.

Y un campo para la extensión que pone la versión usada y que está activada. Con esto ya está.

Generando la información

Es muy fácil, nos aseguramos que la ruta de los logs (/var/www/apd) tiene permisos para que Apache escriba en ella y luego solo tenemos que añadir una línea a nuestro script para que empiece a analizar:

<?php apd_set_pprof_trace() ?>

Hay que añadirla al principio del script, por ejemplo esto en WordPress sería en el fichero wp-blog-header.php sin dejar espacios (aunque sí que vale un salto de línea) entre ése código y el <?php que inicia el código de WordPress. Esto es importante porque de lo contrario dará errores de cabeceras enviadas erróneamente (exactamente igual que con los plugins).

Traduciendo a idioma humano

Ahora, cada petición que hagamos genera un reporte un blog de WordPress recién creado sin nada más que lo básico genera un reporte de 300KB, por lo que hay que tener cuidado de no saturar la máquina: abriremos sólo las páginas que queremos ver su rendimiento (por ejemplo la portada).

Luego, supongamos que el primer reporte que hacemos es el de la portada y se llama pprof.10422.1 pues para traducirlo a algo entendible por nosotros usaremos pprofp.

pprofp -u pprof.10422.1

Con esto ya tenemos el reporte hecho.

¿Un ejemplo de reporte?

WordPress recién instalado, la portada saca esto:

Trace for /var/www/wordpress/wp-blog-header.php
Total Elapsed Time = 0.27
Total System Time  = 0.02
Total User Time    = 0.24

         Real         User        System             secs/    cumm
%Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
--------------------------------------------------------------------------------------
8.5 0.01 0.01  0.02 0.02  0.00 0.00   115  0.0002   0.0002            0 function_exists
6.8 0.01 0.01  0.02 0.02  0.00 0.00  1110  0.0000   0.0000            0 strlen
6.8 0.02 0.02  0.02 0.02  0.00 0.00   210  0.0001   0.0001            0 serialize
5.1 0.01 0.06  0.01 0.06  0.00 0.00   377  0.0000   0.0001            0 apply_filters
5.1 0.00 0.00  0.01 0.01  0.00 0.00   163  0.0001   0.0001            0 preg_match
3.4 0.01 0.01  0.01 0.01  0.00 0.00   194  0.0000   0.0000            0 WP_Object_Cache->get
3.4 0.01 0.01  0.01 0.01  0.00 0.00     4  0.0020   0.0020            0 dirname
1.7 0.00 0.00  0.00 0.00  0.00 0.00     2  0.0020   0.0020            0 include_once
1.7 0.00 0.00  0.00 0.00  0.00 0.00   171  0.0000   0.0000            0 trim
1.7 0.00 0.00  0.00 0.00  0.00 0.00    15  0.0003   0.0003            0 date
1.7 0.00 0.00  0.00 0.00  0.00 0.00   137  0.0000   0.0000            0 mysql_fetch_field
1.7 0.00 0.00  0.00 0.00  0.00 0.00   333  0.0000   0.0000            0 chr
1.7 0.00 0.00  0.00 0.00  0.00 0.00    19  0.0002   0.0002            0 preg_split
1.7 0.00 0.00  0.00 0.00  0.00 0.00    11  0.0004   0.0004            0 is_callable
1.7 0.00 0.12  0.00 0.10  0.00 0.01   148  0.0000   0.0007            0 call_user_func_array
1.7 0.00 0.00  0.00 0.00  0.00 0.00     3  0.0013   0.0013            0 mktime
1.7 0.00 0.00  0.00 0.00  0.00 0.00   163  0.0000   0.0000            0 mysql_num_fields
1.7 0.00 0.00  0.00 0.00  0.00 0.00   167  0.0000   0.0000            0 array_slice
1.7 0.00 0.00  0.00 0.00  0.00 0.00    60  0.0001   0.0001            0 strpos
1.7 0.00 0.00  0.00 0.00  0.00 0.00     1  0.0040   0.0040            0 ini_get

Lo cual coincide con lo que saca en forma de comentario en el HTML:

<!-- 28 queries. 0.269 seconds. -->

Así que a partir de ahí, sólo es cuestión de ver qué nivel de profundidad en la información deseamos y/o podemos manejar. Y por supuesto saber interpretarlo para ver donde podemos optimizar...

¿Algo más?

¡Sí! Al ejecutar pprofp_ me ha dado un error ya que ha intentado encontrar php en /usr/local/bin, lo he arreglado con un enlace simbólico:

ln -s /usr/bin/php5 /usr/local/bin/php

Repito... ¿ALGO MÁS? ###

No... }:P

Comentarios