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.
