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.
