26 de marzo de 2010

Pruebas "tontas" de rendimiento

Hoy una prueba cortita, pero no por ello menos interesante. Simplemente quería constatar, para unas cosas que estoy haciendo en mi framework, lo que tarda un metodo synchronized vs. uno no synchronized y lo que tarda una llamada a un metodo por reflexión vs. llamarlo directamente.

El hardware usado en las pruebas ha sido un portatil Apple MacBook Pro. Esto es básicamente un procesador Core 2 Duo de Intel a 2,53GHz y 4GB RAM. En realidad el hardware nos da lo mismo porque lo que queremos medir son los tiempos relativos de una cosa frente a otra.

El software es un Mac OS X 10.6 y, lo más importante, la versión de Java es la 1.6.0_17. En principio el JRE de Mac es el de Sun, pero como le meten algunas modificaciones en Apple, sería bueno que alguien ejecutase los tests en un Windows y/o en un Linux. Supongo que darán lo mismo, pero sería bueno saberlo. Al final del post añado el código fuente del programa que he usado para probar por si alguno os animáis ;-).

Y aquí van los resultados (todos los tiempos son en milisegundos). Como era de esperar, corresponden con lo que ya sabemos todos más o menos intuitivamente. Os ruego que si veis algún defecto de método me lo comentéis (no hace falta que me digáis que la función desviación que uso no es la formal que se usa en estadística, que ya lo sé; uso este método "alternativo" porque el resultado es más intuitivo que la desviación estándar para el común de los mortales).


Llamada por reflexión vs Llamada directa
  • Número de veces que se ejecuta cada test: 10
  • Iteraciones por test: 100.000.000
  • Llamada por reflexión:
    • Tiempo consumido total: 14.994
    • Media por ejecución: 1.499,4
    • Porcentaje de desviación: 1,854%
  • Llamada directa:
    • Tiempo consumido total: 733
    • Media por ejecución: 73,3
    • Porcentaje de desviación: 1,501%
Conclusión: una llamada a un método por reflexión tarda unas 20 veces más que la llamada directa. Lo bueno es que, aunque es una barbaridad, en realidad en tiempo absoluto es tan pequeño que en la practica nos suele dar un poco igual (porque normalmente el método en si tarda mucho más que la invocación). Sin embargo, si empezamos a llamar a muchos métodos muy cortos por reflexión igual lo empecemos a notar.

Otra pregunta importante a destacar es: ¿por qué? ¿Por qué tiene que tardar tanto? Internamente debería ser mas o menos parecido (creo yo). Molaría que lo optimizasen un poco más. A lo mejor le echo un ojo al código fuente del JRE a ver. Ya os contaré.


Llamada synchronized vs Llamada no synchronized vs Llamada protegida por un Lock

Por supuesto es desde un solo thread. Es decir, el synchronized no se para nunca, solo hace el chequeo.
  • Número de veces que se ejecuta cada test: 10
  • Iteraciones por test: 100.000.000
  • Llamada synchronized:
    • Tiempo consumido total: 29.918
    • Media por ejecución: 2.991,8
    • Porcentaje de desviación: 0,949%
  • Llamada directa:
    • Tiempo consumido total: 791
    • Media por ejecución: 79,1
    • Porcentaje de desviación: 12,516%
  • Llamada protegida por Lock:
    • Tiempo consumido total: 25.989
    • Media por ejecución: 2.598,9
    • Porcentaje de desviación: 1,243%
En este caso, el ratio synchronized/no synchronized es de casi 38 veces más. Es decir, peor aún que la reflexión es el synchronized. Si llamamos a un método synchronized por reflexión tarda lo esperado: un poco más que la suma de las dos cosas. Es decir, el comportamiento es lineal.

En cuanto a usar Lock o synchronized, yo daría que da igual.


Y como lo prometido es deuda, aquí va el código fuente

import java.lang.reflect.Method;
import java.util.concurrent.locks.ReentrantLock;


public class Main {

    /**
     * @param args
     */
    public static void main( String[] args ) {
        try {
            int times = 10;
            long[] total = new long[times];
            long[] iters =  { 
                100000000, 100000000, 100000000, 100000000, 100000000, 100000000
            };
            String[] tests = { 
                "Reflection", "NonReflection", "Synchronized", "NonSynchronized", "SynchronizedReflection", "Locked"    
            };
            
            if( iters.length != tests.length ){
                throw new IllegalStateException("Sizes of iters and tests differ");
            }

            for( int i=0 ; i
                String test = tests[i];
                long iterations = iters[i];
                
                System.out.println("=========================================");
                System.out.println("Test:           "+test);
                System.out.println("Iterations:     "+iterations);
                
                for( int t=0 ; t
                    total[t] = runTest( test, iterations );
                }

                long grandTotal = 0;
                for( int t=0 ; t
                    grandTotal += total[t];
                }
                long grandAvg = grandTotal/times;
                
                long deviation = 0;
                for( int t=0 ; t
                    long pdev = total[t] - grandAvg;
                    if( pdev<0 ){
                        pdev = -pdev;
                    }
                    deviation += pdev;
                }
                
                System.out.println("Grand total:    "+grandTotal);
                System.out.println("Average:        "+(1.0*grandTotal/times));
                System.out.println("Dev:            "+(1.0*deviation/times));
                System.out.println("Dev %:          "+(100.0*deviation/times)/(1.0*grandTotal/times));
                System.out.printf( "Time/Iteration: %.4f\n",(1.0*grandTotal/(times*iterations)));
                
            }
            
        } catch( Throwable t ){
            t.printStackTrace();
        }
    }

    public static long runTest( String test, long iterations ) throws Exception {
        try {
            Main.class.getMethod( "init"+test ).invoke( null );
        } catch( NoSuchMethodException e ){
            // ignore
        }
        long start = System.currentTimeMillis();
        Main.class.getMethod( "run"+test, long.class ).invoke( null, iterations );
        return System.currentTimeMillis()-start;
    }
    
    ///////////////////////////////////////////////////////////////////////////
    private static Method m;
    private static ReentrantLock lock = new ReentrantLock();
    
    public static void initReflection() throws Exception {
        m = Main.class.getMethod( "emptyMethod" );
    }

    public static void runReflection( long iterations ) throws Exception {
        for( long i=0 ; i
            m.invoke( null );
        }
    }
    
    public static void runNonReflection( long iterations ) throws Exception {
        for( long i=0 ; i
            emptyMethod();
        }
    }
    
    public static void runSynchronized( long iterations ) throws Exception {
        for( long i=0 ; i
            synchedMethod();
        }
    }
    
    public static void runNonSynchronized( long iterations ) throws Exception {
        for( long i=0 ; i
            nonSynchedMethod();
        }
    }

    public static void initSynchronizedReflection() throws Exception {
        m = Main.class.getMethod( "emptySynchedMethod" );
    }

    public static void runSynchronizedReflection( long iterations ) throws Exception {
        for( long i=0 ; i
            m.invoke( null );
        }
    }
    
    public static void runLocked( long iterations ) throws Exception {
        for( long i=0 ; i
            lockedMethod();
        }
    }
    
    public static void runNonLocked( long iterations ) throws Exception {
        for( long i=0 ; i
            nonLockedMethod();
        }
    }

    ///////////////////////////////////////////////////////////////////////////
    
    public static void emptyMethod() {
    }

    public static void nonSynchedMethod() {
    }

    public synchronized static void synchedMethod() {
    }

    public synchronized static void emptySynchedMethod() {
    }

    public static void lockedMethod() {
        lock.lock();
        lock.unlock();
    }

    public static void nonLockedMethod() {
        
    }
}

12 de marzo de 2010

Más herramientas para análisis del heap de Java

Como resultado final del análisis de memoria que he comentado en los anteriores artículos, voy a hacer una recopilación del metodo de análisis empleado y las herramientas que nos han sido útiles.

Paso 1. Reproducir el problema

Para hallar un goteo de memoria a partir de la version 5 de Java, lo más comodo es arrancar el servidor de aplicaciones/servlets con los siguientes parámetros:

-Dcom.sun.management.jmxremote 
-Dcom.sun.management.jmxremote.port=9696 
-Dcom.sun.management.jmxremote.authenticate=false 
-Dcom.sun.management.jmxremote.ssl=false

Estos parámetros hay que pasárselos a la JVM del servidor. Dependiendo del servidor esto se hará en un fichero u otro de configuración. Por ejemplo, en Tomcat basta con definir una variable de entorno llamada JAVA_OPTS antes de lanzar el Tomcat.

Una vez lanzado el servidor ejecutamos el programa jconsole, que viene con el JDK y nos conectamos al servidor. Podemos identificarlo por el PID si hemos lanzado el jconsole en la misma máquina que el servidor o conectarnos en remoto poniendo la IP del servidor más el puerto que hemos definido en los parámetros (en nuestro caso el 9696).

Con el jconsole podemos visualizar en tiempo real el consumo del heap y forzar a la JVM a que haga recolecciones de basura. Ahora solo queda ir navegando por la aplicación hasta identificar la operativa que causa el gasto/goteo de memoria. Como esto depende de la aplicación tendreis que ser suficientemente ingeniosos como para poder reproducir el problema y detectar donde se produce.

Paso 2. Encontrar la causa del problema

Una vez que logramos reproducir el goteo de memoria, ya solo nos queda averiguar que es lo que no se está limpiando de la memoria. Para ello, lo mas comodo es hacer un volcado del heap de Java y luego analizarlo para ver que objetos consumen más. Para ello vamos a usar cuatro herramientas:

  • jmap (viene con el JDK): hace volcados del heap del proceso JVM que le digamos
  • gcore (solo en Unix): hace volcados nativos de la memoria de un proceso (los famosos core dumps)
  • HeapAnalyzer (de IBM): analiza los volcados de memoria de forma gráfica
  • Memory Analyzer Tool (de Eclipse): analiza los volcados de memoria de forma gráfica

Para hacer un volcado del heap de la JVM basta con ejecutar (con el servidor corriendo, obviamente):

jmap -dump:format=b,file=dump.hprof PID_del_servidor

Así de simple. Esto nos generará un fichero llamado dump.hprof que podremos analizar con el HeapAnalyzer de IBM (que se puede descargar de aquí) o con el Memory Analyzer Tool de Eclipse (que se puede descargar de aquí). Cualquiera de estas dos herramientas es capaz de mostrarnos un árbol con todos los objetos cargados en la JVM y las dependencias entre ellos (quién contiene a quién). Con esa información y sabiendo como está estructurada la aplicación podremos saber en que se pierde la memoria.

Paso 3 (opcional). Modo pánico: ¡no funciona el jmap!

Los observadores os habreis dado cuenta de que no he dicho nada de gcore. Eso es porque, en principio, esa herramienta no nos hace falta. Sin embargo, es posible que el jmap no os funcione bien (a nosotros nos daba una NullPointerException al usarlo) porque es una herramienta experimental. Entonces, hay una solucion de emergencia que consiste en ejecutar:

gcore PID_del_servidor

Esto nos generará un "core dump" de Unix que podremos pasarle al jmap para que nos genere el dump.hprof, como si nos hubiesemos conectado al servidor con el jmap. Para esto hay que ejecutar el comando:

jmap -dump:format=b,file=dump.hprof $JAVA_HOME/java Archivo_del_core_dump

Esto lanzara la JVM con el debugger de Unix enganchado a ella, cargará el core dump, y después el jmap volcará el heap de la JVM. Despues, analizaremos el dump del heap con las dos herramientas de análisis.

Paso 4 (todavía más opcional). Modo pánico*2: ¡no funciona el jmap! ¡no tengo el gcore!


Si estais en Windows o en Unix en donde no existe gcore y no os funciona el jmap, entonces no está todo perdido. Aún nos queda una bala en la recámara consistente en lanzar el servidor pasándole el siguiente parámetro:


-XX:+HeapDumpOnOutOfMemoryError


Este parámetro causa la generación de un volcado automático cuando se produce un OutOfMemoryError. Una vez se genere el volcado, lo podeis analizar con las herramientas habituales.

En fin, eso es todo. Espero que este pequeño artículo os sea de ayuda a la hora de diagnosticar un goteo de memoria o un OutOfMemoryError.

Seguiremos informando.


Desenlace de las pruebas de uso de memoria en nuestra aplicación Icefaces

Esta semana hemos seguido diagnosticando errores de memoría. Y por fin hemos dado con la solución: ni goteo de memoria, ni Icefaces, ni JSF, ni nada. Al final el servidor se caía porque se quedaba sin memoria, pero memoria que necesitaba realmente.

Os preguntareis, ¿por qué no fue lo primero que probasteis (subir el limite máximo de memoria de la JVM con el parámetro -Xmx)? Y la respuesta es: por dos motivos, el primero que la aplicación está en producción de un cliente muy grande y no es tan fácil cambiar esos parámetros sin argumentar por qué. El segundo: que si no sabemos si es que necesita más memoria o es que tiene un goteo, no parece muy ético subir el parámetro y dejarlo correr.

Esto último tiene un nombre: solución de problemas/programación por coincidencia. Es una práctica que, lamentablemente, estoy harto de ver y que consiste en dar palos de ciego toqueteando todo hasta que funciona. Y cuando funciona "me olvido y tiro p'alante", sin saber realmente si se ha arreglado o no, ni por que se ha arreglado.

No lo hagais más, anda :-P.

En fin, al grano, al final el problema es que nos habían reservado 256MB para la JVM y, después de dar un OutOfMemoryError, analizando un volcado del heap de la JVM resulta que de 100MB de heap que teníamos disponibles (sí, los otros 156MB se los comía el servidor de aplicaciones él solito) 81MB estabán ocupados por la clase WebAppClassLoader. Efectivamente, nuestro WAR ocupa 50MB y el classloader se lo tiene que guardar casi entero en memoria (tened en cuenta que lo que más ocupa en una aplicación web suelen ser los JAR) porque almacena el contenido de cada .class en un array de bytes más otras cositas asociadas.

Conclusión: nos quedaban unos 19MB para ejecutar nuestra aplicación. Y eso habiendo cargado solo un 70% de las clases totales de la aplicación. Así que, la solución propuesta ha sido subir el limite a 512MB y seguir probando.

Yo tengo fe en que se solucione, pero si vuelve a fallar, volveremos a hacer más pruebas, y volveré a abrasaros con otro artículo ;-P.

5 de marzo de 2010

Liberada la version 1.0 de las ariadna-tools

Al hilo del artículo anterior sobre goteos de memoria en Java, he compilado la librería JNI de la herramienta ariadna para Mac OS X 10.6, que es la plataforma que habitualmente uso para trabajar.

Ariadna es un profiler de la JVM sencillito que es capaz de volcar todo el contenido del heap cuando se le pide. Despues podemos navegar el contenido del heap a traves de páginas HTML viendo que objetos hay y por quien son referenciados. Es una buena herramienta de bajo nivel para ayudar a depurar goteos de memoria (o "memory leaks", como prefirais).

El proyecto está en Google code, y contiene tambien la página JSP que se cita en el artículo antedicho. Por si quereis echarle un ojo, o descargarlo, os dejo aquí la URL:

http://code.google.com/p/factoria2-tools/downloads/list

Espero que os sea de ayuda. Ya me contaréis los que lo useis que os ha parecido. Y no olvideis que cualquier contribución al proyecto será gratamente aceptada.

Al final Icefaces no parece tener Alzheimer ;-)

En referencia a mi artículo anterior sobre memory leaks en Icefaces, ya he estado haciendo varias pruebas y no parece que haya ningún problema con la memoria e Icefaces. Lo único que he encontrado es que la memoria minima necesitada por Icefaces es directamente proporcional al número de threads que tiene Tomcat lanzados en un momento dado. Es decir, que cuanto más estresemos una aplicación Icefaces, más threads lanzará Tomcat, y más memoria consumirá la JVM.

Por lo demás, el uso de memoria es normal. Sí es cierto, como os comente, que refrescando cualquier página, cuando Icefaces tiene el com.icesoft.faces.concurrentDOMViews activado, el uso de memoria se dispara. Esto es debido a que Icefaces, por cada nuevo refresco, se crea un árbol nuevo de componentes JSF y lo guarda en sesión (si tenemos JSF configurado para que el árbol se guarde en sesión, claro).

Sin embargo, esta reserva de memoria se limpia al finalizar la sesión y, salvo que crezca muy deprisa o no se liberen las suficientes sesiones, no debería dar problemas puesto que es recuperada correctamente por el recolector de basura.

En cualquier caso, como parece que este asunto del goteo de memoria con la aplicación Icefaces nos va a seguir persiguiendo unos días más, os mantendré informados de futuras averiguaciones.