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() {
        
    }
}

No hay comentarios:

Publicar un comentario