[php] Depurando / Profiling en php ( II )

En este caso analizamos un hecho real, una web que tarda en cargar aleatoriamente entre 10 y 12 segundos. El problema es que al medir los tiempos en otro servidor no llega a 2 segundos. Después de revisar conectividad, carga de sistema, carga de apache … y demás parámetros habituales; todo estaba perfecto. Así que decidimos relizar el profiling de la web para localizar el cuello de botella dentro de los scripts php.

En el artículo anterior [php] Depurando / Profiling en php ( I ) dejamos instalado el módulo APD para capturar la información necesaria y luego procesarla. Recordamos que hay que usar la función apd_set_pprof_trace(); para que se generen los datos. En nuestro caso hemos seleccionado la ruta /tmp en donde se almacenarán estos ficheros.

Ejecutamos unos cuantas veces el script php que nos interesa. Generamos una captura de una ejecución en 1-2 segundos (/tmp/pprof.32231.1) y seguimos ejecutando hasta que conseguimos una captura de datos de una ejecución que tardó unos 10-11 segundos (/tmp/pprof.01666.0)

Vamos a comparar la captura de los datos :

La ejecución buena :

# pprofp -R /tmp/pprof.32231.1

Trace for /var/www/vhosts/hostingaldescubierto.com/httpdocs/index.php
Total Elapsed Time = 0.36
Total System Time  = 0.03
Total User Time    = 0.07

Real         User        System             secs/    cumm
%Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
--------------------------------------------------------------------------------------
100.0 0.00 0.36  0.00 0.07  0.00 0.03     1  0.0000   0.3589            0 main
96.1 0.00 0.34  0.00 0.08  0.00 0.03     5  0.0000   0.0690            0 require_once
59.1 0.00 0.21  0.00 0.01  0.00 0.00     8  0.0000   0.0265            0 include
58.9 0.00 0.21  0.00 0.01  0.00 0.00     1  0.0000   0.2113            0 call_user_func_array
58.9 0.00 0.21  0.00 0.01  0.00 0.00     1  0.0000   0.2113            0 Pages->index
58.9 0.00 0.21  0.00 0.01  0.00 0.00     1  0.0000   0.2112            0 Pages->show
58.9 0.00 0.21  0.00 0.01  0.00 0.00     1  0.0000   0.2112            0 Template->build
58.8 0.00 0.21  0.00 0.01  0.00 0.00     2  0.0000   0.1054            0 MY_Loader->view
58.6 0.00 0.21  0.00 0.01  0.00 0.00     2  0.0000   0.1052            0 MY_Loader->_ci_load
56.8 0.00 0.20  0.00 0.00  0.00 0.00     1  0.0000   0.2038            0 weather_google_api
56.8 0.20 0.20  0.00 0.00  0.00 0.00     1  0.2037   0.2037            0 simplexml_load_file
29.4 0.00 0.11  0.00 0.05  0.00 0.02     1  0.0000   0.1054            0 Pages->Pages
29.2 0.00 0.10  0.00 0.05  0.00 0.02     1  0.0000   0.1048            0 Pages->Public_Controller
13.9 0.00 0.05  0.00 0.03  0.00 0.02     1  0.0000   0.0497            0 Pages->MY_Controller
13.4 0.00 0.05  0.00 0.02  0.00 0.03     2  0.0000   0.0241            0 MY_Loader->_ci_autoloader
12.2 0.00 0.04  0.00 0.01  0.00 0.00     3  0.0000   0.0146            0 Banners_model->get_by_section
11.7 0.00 0.04  0.00 0.00  0.00 0.00    25  0.0000   0.0017            0 CI_DB_mysql_driver->query
11.5 0.00 0.04  0.00 0.01  0.00 0.00     6  0.0000   0.0069            0 Banners_model->add_hit
11.4 0.04 0.04  0.03 0.03  0.01 0.01    65  0.0006   0.0006            0 defined
10.9 0.00 0.04  0.00 0.00  0.00 0.00    25  0.0000   0.0016            0 CI_DB_mysql_driver->simple_query

El fichero de 10-12 segundos :

# pprofp -R /tmp/pprof.01666.0

Trace for /var/www/vhosts/hostingaldescubierto.com/httpdocs/index.php
Total Elapsed Time = 10.34
Total System Time  = 0.02
Total User Time    = 0.08

Real         User        System             secs/    cumm
%Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
--------------------------------------------------------------------------------------
100.1 0.00 10.35  0.00 0.09  0.00 0.02     5  0.0000   2.0692            0 require_once
100.0 0.00 10.34  0.00 0.08  0.00 0.02     1  0.0000   10.3394            0 main
99.1 0.00 10.24  0.00 0.01  0.00 0.00     8  0.0000   1.2802            0 include
99.0 0.00 10.24  0.00 0.01  0.00 0.00     1  0.0000   10.2409            0 call_user_func_array
99.0 0.00 10.24  0.00 0.01  0.00 0.00     1  0.0000   10.2409            0 Pages->index
99.0 0.00 10.24  0.00 0.01  0.00 0.00     1  0.0000   10.2409            0 Pages->show
99.0 0.00 10.24  0.00 0.01  0.00 0.00     1  0.0000   10.2409            0 Template->build
99.0 0.00 10.24  0.00 0.01  0.00 0.00     2  0.0000   5.1202            0 MY_Loader->view
99.0 0.00 10.24  0.00 0.01  0.00 0.00     2  0.0000   5.1200            0 MY_Loader->_ci_load
99.0 0.00 10.23  0.00 0.00  0.00 0.00     1  0.0000   10.2335            0 weather_google_api
99.0 10.23 10.23  0.00 0.00  0.00 0.00     1  10.2333   10.2333            0 simplexml_load_file
0.7 0.00 0.08  0.00 0.06  0.00 0.01     1  0.0000   0.0766            0 Pages->Pages
0.7 0.00 0.08  0.00 0.05  0.00 0.01     1  0.0000   0.0761            0 Pages->Public_Controller
0.5 0.00 0.05  0.00 0.04  0.00 0.01     2  0.0000   0.0266            0 MY_Loader->_ci_autoloader
0.5 0.00 0.05  0.00 0.04  0.00 0.01     1  0.0000   0.0524            0 Pages->MY_Controller
0.4 0.04 0.04  0.04 0.04  0.01 0.01    65  0.0006   0.0006            0 defined
0.4 0.00 0.04  0.00 0.02  0.00 0.01    38  0.0000   0.0010            0 MY_Loader->helper
0.3 0.00 0.04  0.00 0.03  0.00 0.00    10  0.0000   0.0036            0 MY_Loader->model
0.3 0.00 0.03  0.00 0.02  0.00 0.01     1  0.0000   0.0312            0 Pages->Controller
0.3 0.00 0.03  0.00 0.02  0.00 0.01     1  0.0000   0.0311            0 Pages->_ci_initialize

Vemos claramente esta linea que es la que penaliza el tiempo de ejecución del script:

99.0 10.23 10.23  0.00 0.00  0.00 0.00     1  10.2333   10.2333            0 simplexml_load_file

Perfecto, ya sabemos lo que tenemos que buscar el uso de la función simplexml_load_file. Buscamos los ficheros que usan esta funcion, por ejemplo así :

find -name "*php" -exec grep -l simplexml_load_file {} ;

Entre los resultados encontramos uno, que llama especialmente la atención, en el que solicita un fichero xml de google http://www.google.com/ig/api?weather=madrid&oe=utf-8.
Vamos a medir cuanto tiempo tarda en descargarlo :

# time wget 'http://www.google.com/ig/api?weather=madrid&oe=utf-8'
--2010-07-26 18:27:47--  http://www.google.com/ig/api?weather=madrid&oe=utf-8
Resolving www.google.com... 66.249.92.104
Connecting to www.google.com|66.249.92.104|:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/xml]
Saving to: `api?weather=madrid&oe=utf-8.1'

[ <=>                                                                                                                                      ] 1,291       --.-K/s   in 0s

2010-07-26 18:27:57 (12.0 MB/s) - `api?weather=madrid&oe=utf-8.1' saved [1291]

real    0m10.157s
user    0m0.002s
sys    0m0.001s

Parece bastante claro que la ejecución se ralentiza por la petición a google… una caché que se actualice cada día, hora o cada minuto solucionaría este problema.

Una respuesta a «[php] Depurando / Profiling en php ( II )»

Deja un comentario

Tu dirección de correo electrónico no será publicada. Los campos obligatorios están marcados con *

 

Este sitio usa Akismet para reducir el spam. Aprende cómo se procesan los datos de tus comentarios.