[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.

[php] Depurando / Profiling en php ( I )

Para poder diagnosticar qué sucede en la máquina cuando se ejecuta un script en php es necesario instalar un depurador o profiler. En este caso instalamos Advanced Php Debugger.

En máquinas Centos, como es usual no lo tenemos en el repositorio así lo instalaremos manualmente usando ‘pecl‘ que lo provee el paquete de php-pear .

pecl install apd

Será necesario tener instalado make, gcc  y autconf

Nos podemos encontrar con este error :

# pecl install apd
WARNING: channel "pear.php.net" has updated its protocols, use "channel-update pear.php.net" to update
downloading apd-1.0.1.tgz ...
Starting to download apd-1.0.1.tgz (36,643 bytes)
..........done: 36,643 bytes
15 source files, building
running: phpize
Configuring for:
PHP Api Version:         20041225
Zend Module Api No:      20060613
Zend Extension Api No:   220060519
building in /var/tmp/pear-build-root/apd-1.0.1
running: /tmp/pear/download/apd-1.0.1/configure
checking for egrep... grep -E
checking for a sed that does not truncate output... //bin/sed
checking for cc... cc
checking for C compiler default output file name... a.out
checking whether the C compiler works... configure: error: cannot run C compiled programs.
If you meant to cross compile, use `--host'.
See `config.log' for more details.
ERROR: `/tmp/pear/download/apd-1.0.1/configure' failed

Normalmente es debido a que tenemos /var y /var/tmp con la opcion de noexec. Para poder ejecutarlo correctamente pondremos temporalmente estos puntos de montaje con permisos de ejecución y luego lo restauramos:

mount -o,remount,rw,exec /var/tmp
mount -o,remount,rw,exec /tmp
pecl install apd
mount -o,remount,rw,noexec /var/tmp
mount -o,remount,rw,noexec /tmp

Nos insteresa quedarnos con este contenido para configurar el fichero .ini :

running: make INSTALL_ROOT="/var/tmp/pear-build-root/install-apd-1.0.1" install
Installing shared extensions:     /var/tmp/pear-build-root/install-apd-1.0.1/usr/lib64/php/modules/
running: find "/var/tmp/pear-build-root/install-apd-1.0.1" | xargs ls -dils
  12   1 drwxr-xr-x 3 root root   1024 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1
2057   1 drwxr-xr-x 3 root root   1024 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1/usr
4113   1 drwxr-xr-x 3 root root   1024 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1/usr/lib64
6169   1 drwxr-xr-x 3 root root   1024 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1/usr/lib64/php
8225   1 drwxr-xr-x 2 root root   1024 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1/usr/lib64/php/modules
8226 129 -rwxr-xr-x 1 root root 130196 Jul 23 18:33 /var/tmp/pear-build-root/install-apd-1.0.1/usr/lib64/php/modules/apd.so

Build process completed successfully
Installing '/usr/lib64/php/modules/apd.so'
install ok: channel://pear.php.net/apd-1.0.1

Tendremos que crear un fichero en /etc/php.d/apd.ini con este contenido

zend_extension = /usr/lib64/php/modules/apd.so
apd.dumpdir = /tmp
apd.statement_tracing = 0

y comprobamos que el modulo carga con php -m

#php -m

....

[Zend Modules]
Advanced PHP Debugger (APD)
Zend Optimizer

Ahora ya podemos lanzar el profiling en nuestras páginas, para ello podemos incrustar este fragmento de código y activarlo sólamente cuando accedamos nosotros y no los clientes:

 <?php
 $DEBUGIPS = array('93.174.6.8','192.168.1.1');
 if(array_search($_SERVER[REMOTE_IP], $DEBUGIPS)) {
   apd_set_pprof_trace();
 }
?> 

Y con esto acabamos la primera parte, atentos a la segunda 😀

[magento] PHP Fatal error: Exception thrown without a stack frame in Unknown on line 0

Estos últimas días hemos tenido que optimizar la carga de servidores con Magento. Una de las tareas es usar un sistema de caché que acelere los scripts php. Usamos apc por compatibilidad con Magento y por que ya viene paquetizado en los repositorios de Debian.

El problema, aparece en el pié de página: “PHP Fatal error:  Exception thrown without a stack frame in Unknown on line 0”.
Este error aparece cuando se ha lanzado una excepcion en un lugar donde se no se puede lanzar una excepción por no tener ‘stack frame‘.

Los manejadores de excepciones ‘ exception handlers‘ y los destructores no tienen ‘stack frame‘.
Por lo que combinar por ejemplo un ‘execption handler‘ con un ‘error preporting‘  o lanzar un execption en un destructor puede provocar que aparezcan. Os podeis documentar más en este interesante enlace Solving “Fatal error: Exception thrown without a stack frame in Unknown on line 0″

En nuestro caso, tan solo hizo falta acutalizar la version del apc con un simple aptapt-get install php-apc

En la máquina estaba previamente instalado el apc vía pecl

safe_mode y wordpress

Una forma elegante de resolver el problema de permisos con wordpress teniendo safe_mode activo es la siguiente.

Podremos permisos 7777 ( sticky + guid ) a la carpeta de uploads

chmod 7777 /var/www/vhosts/midominio.com/httpdocs/wp-content/uploads

y agregamos esta linea al fichero /var/www/vhosts/midominio.com/conf/vhost.conf :

php_admin_flag safe_mode_gid  "On"

Con esta directiva le indicamos al motor php que sólo compruebe el grupo en las directivas de safe_mode. Como tiene permisos de stick y guid, los ficheros subidos heredaran el grupo al que pertenece la carpeta ‘uploads’

Para que este cambio quede correctamente funcionando hay que lanzar el reconfigurador ( en caso de plesk ) y recargar el apache:

/usr/local/psa/admin/bin/websrvmng --reconfigure-vhost --vhost-name=midominio.com

apachectl graceful ó apache2ctl graceful para debian