Profiling en PHP: ¿qué partes consumen más?
Publicado el Viernes 31 de Agosto del 2007 @ 5:22 por Armonth.
Hace relativamente poco comentaba casi de pasada lo bien que iría tener una utilidad para saber qué funciones de PHP consumen más a lo cual el primer comentario comentaba la respuesta: herramientas de profiling para PHP.
Ayer le dediqué un rato al tema y si bien veo que sería más fácil algo integrado en WordPress, hay que reconocer que es más práctico hacerlo con profiling genérico ya 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() 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 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. -->
¿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
También, como ya me pasó anteriormente, el mencionar phpinfo() y apd_set_pprof_trace() con el “;” final hace que salte mod_security y me impide publicar esto, así que si bien normalmente las funciones funcionan igual terminadas en () que en () + ; si os da problemas usad la segunda forma…
Repito… ¿ALGO MÁS?
No… }:P
7 Comentarios (feed)
-
Croc nos comenta:
Recuerdo que hace tiempo intenté probar sin éxito el Xdebug para una aplicación que me destrozaba los recursos, y al final acabé desistiendo. Intentaré ahora retomarlo gracias a esta entrada ;)
Del informe que has puesto de un WP peladito se puede ver que la función que más se usa es “strlen” (más de 1100 llamadas! pero sin consumo relevante) seguida muy de lejos por “apply_filters” y “chr”. Las llamadas más pesadas, es decir que consumen más tiempo individualmente son “ini_get”, “dirname”, “include_once” y “mktime”. Pero como se llaman pocas veces al final no representan tanto tiempo consumido del total, ya que otras funciones más livianas, pero invocadas muchas veces más son las que al final se llevan el procesador por delante (indicado por la cantidad en % de la primera columna y ordenados por ella).
No creo que sea muy factible implementar algo similar dentro de WP, ya que la sobrecarga sería exagerada e injustificada existiendo alternativas externas como ésta. Tampoco hay que descartar que la base de datos se lleva un buen pico de tiempo de procesamiento, y teóricamente debería ser más sencillo intentar optimizar las consultas y su cantidad.
Lo que no me acaba de convencer es que debe colocarse el inicio del profiling en wp-blog-header.php. Lo primero que se invoca y después va delegando no es el propio index.php?
Un saludo!
-
Técnico CQP nos comenta:
Feliz BlogDay 2007
Estás entre mis cinco blogs recomendados de este año.
http://cqp.blogspot.com/2007/08/feliz-blog-day-2007.html
Saludos.
-
Croc nos comenta:
Ahora que he tenido un rato he visto el contenido del index.php, no lo recordaba tan “escueto” :P El “wp-blog-header.php” es correcto entonces ^^
Nada más que añadir al artículo :)
Salu2! -
Manz nos comenta:
Simplemente brillante, Armonth ;)
-
Armonth nos comenta:
Eso iba a decir Croc… dos líneas y una es un “define” :-).
Manz, CQP, gracias :-)
-
mailero nos comenta:
¿ Se puede usar apd en windows ? Gracias
-
David Carrero Fdez-Baillo nos comenta:
Simplemente genial, lo estoy probando y es realmente útil ;)