domingo, 30 de junio de 2013

Exception Stack Trace: Desaparecido En Combate

Escenario


Un día como otro cualquiera estás depurando un programa en Java cuando se produce una excepción, pongamos por ejemplo de tipo NullPointerException, por lo que decides ir tranquilamente a mirar los ficheros de log y sólo te encuentras esto:

java.lang.NullPointerException

Aún perplejo y con cara de tonto te preguntas: ¡¡Ehhhh!!¿¿Y el Stack Trace??

Como eres un programador concienzudo, consigues reproducir la excepción, vuelves a mirar el fichero de log y lo mismo, la excepción tiene mensaje pero no tiene Stack Trace.

Si te ha pasado esto o si te pasa algún día te interesará seguir leyendo.


¿Qué está pasando y cómo se evita?


Pues lo que ocurre es que el compilador JIT (Just In Time) de la JavaVM ha decido "optimizar" simplificando las excepciones para siempre (bueno, al menos hasta que se vuelva a arrancar la JavaVM).

En el enlace Java 5.0 Release Notes se puede leer el siguiente párrafo:

(...)The compiler in the server VM now provides correct stack backtraces for all "cold" built-in exceptions. For performance purposes, when such an exception is thrown a few times, the method may be recompiled. After recompilation, the compiler may choose a faster tactic using preallocated exceptions that do not provide a stack trace. To disable completely the use of preallocated exceptions, use this new flag:
-XX:-OmitStackTraceInFastThrow.(...)

Que en el idioma de Cervantes viene a decir algo así (me niego a traducir algunos términos):

(...)El compilador en las Server VM ahora proporciona el volcado de pila correcto para todas las excepciones "cold built-in". Por razones de rendimiento, cuando tales excepciones se lanzan unas pocas veces, el método puede ser recompilado. Tras la recompilación, el compilador puede elegir una táctica más rápida utilizando excepciones precalculadas que no proporcionan el volcado de pila. Para deshabilitar por completo el uso de excepciones precalculadas, utilizar el nuevo flag:
-XX:-OmitStackTraceInFastThrow.(...)

O sea, que si no quieres que te pase, tendrás que acordarte de utilizar el suguiente argumento de línea de comandos al arrancar la JavaVM en modo server:

-XX:-OmitStackTraceInFastThrow

Por si no lo sabes, la JavaVM se arranca en modo server con el argumento de línea de comandos "-server":

java -server ...


Programa de demostración


Ejecutando este pequeño programa en una JavaVM en modo server (creo que para ello hace falta el JDK, que con el JRE no es suficiente) se puede comprobar que, tras un cierto número de veces, desaparece el Stack Trace de varios tipos de excepciones.


package pruebas;

public class MissingStackTrace {

    /**
     * Para dar profundidad al StackTrace, se lanza un Exception
     * tras varias invocaciones recursivas.
     * aType indica el tipo de excepción que se desea lanzar.
     */
    private static void throwEx(int aDepth, int aMaxDepth, int aType)
    throws Exception {
        if (aDepth >= aMaxDepth) {
            switch (aType) {
                case 0: {
                    //Se genera una NullPointerException.
                    String badIdea= null;
                    badIdea= badIdea.toString();
                } break;

                case 1: {
                    //Se genera una ArrayIndexOutOfBoundsException.
                    Object[] badIdea= new Object[0];
                    badIdea[0]= null;
                } break;

                default: {
                    //Se genera una ArithmeticException.
                    int badIdea= 100 / 0;
                } break;
            }
        }
        else {
            throwEx(aDepth+1, aMaxDepth, aType);
        }
    }
    //--------------------------------------------------------------------------

    /**
     * Modo de uso:
     *
     * java -server -cp pruebas.MissingStackTrace [número] [profundidad]
     */
    public static void main(String[] args) {
        //Las pruebas indican que el StackTrace desaparece tras 150 excepciones.
        int COUNT= 166;
        int MAX_DEPTH= 20;

        //Se asume que se ha indicado un número de iteraciones.
        if (args.length == 1) {
            COUNT= Integer.parseInt( args[0] );
        }

        //Se asume que se ha indicado la profundid.
        if (args.length == 2) {
            MAX_DEPTH= Integer.parseInt( args[1] );
        }

        //Impresión inicial de la excepción: sí sale Stack Trace.
        for (int i= 0; i < 3; i++) {
            try {
                //Se genera una excepción.
                throwEx(0, MAX_DEPTH, i%3);
            }
            catch (Exception ex) {
                ex.printStackTrace( System.out );
            }
        }

        //Se generan varias excepciones.
        for (int i= 0; i < COUNT; i++) {
            try {
                //Se genera una excepción.
                throwEx(0, MAX_DEPTH, i%3);
            }
            catch (Exception ex) {
                StackTraceElement[] st= ex.getStackTrace();
                System.out.format("i:=%s StackTrace.length=%s Class=%s%n",
                    i, st.length, ex.getClass().getName()
                );
            }
        }

        //Impresión final de la excepción: no sale Stack Trace.
        for (int i= 0; i < 3; i++) {
            try {
                //Se genera una excepción.
                throwEx(0, MAX_DEPTH, i%3);
            }
            catch (Exception ex) {
                ex.printStackTrace( System.out );
            }
        }
    }
    //--------------------------------------------------------------------------

}

Realizando pruebas con JDK 1.6.0_37 desaparece el Stack Trace tras unas 150 excepciones. En la salida del programa, se puede comprobar que tras cierto número de excepciones, la longitud del Stack Trace de los 3 tipos de excepciones que se lanzan pasa de 102 a 0.

Recuerda invocar el programa con el argumento de línea de comandos "-server":

java -server -cp pruebas.MissingStackTrace 166 100

Y cambiar el número de excepciones para hacer pruebas. Las pruebas que he realizado indican que la recompilación depende no sólo del número de excepciones, sino también de la profundidad de los Stack Trace de las mismas.


Conclusiones


Hay que reconocer que como mínimo es curioso que puestos a optimizar, se les ocurra optimizar instrucciones que nunca deberían producirse (de ahí que se llamen excepciones) y que resultan vitales a la hora de solucionar fallos.

Lo peor de todo es que por defecto se optimiza, lo que se puede hacer manualmente es desactivar dicha optimización. En mi humilde opinión, debería ser al revés, es decir, activar la optimización de modo explícito.

Hasta donde mis conocimientos alcanzan, no existe una solución en caliente (Run Time), sino que sólo se puede solventar en el momento de arrancar la JavaVM. ¿Y si resulta que el desarrollador no tiene acceso a la JavaVM como ocurre por ejemplo cuando se usa un Apache Tomcat compartido en algún CPD?

Seguro que los señores de Sun (ahora Oracle) nunca se han visto en la tesitura de tener que explicarle (tras innumerables trámites burocráticos) a un administrador de sistemas que rearranque el Tomcat y que encima modifique los SCRIPTs de arranque sólo porque no se imprimen bien los errores... Casi seguro que eso acaba de una de estas maneras:
  1. El administrador de sistemas te deja claro que el Tomcat está funcionando perfectamente y no piensa tocarlo, y es cierto, tiene toda la razón.
  2. El administrador de sistemas no te entiende ni papa y amablemente desistes.
  3. El administrador de sistemas se parte de la risa y te dice:
    "<sarcasmo on>
    Sí hombre sí, ahora mismito rearranco el Tomcat para tí solito.
    <sarcasmo off>"
Hay que tener en cuenta que en un entorno de ejecución como el Apache Tomcat, el Stack Trace de las excepciones tiene de por sí bastante profundidad antes de llegar al código del usuario y además puede haber muchas aplicaciones generadoras de excepciones ejecutándose a la vez.

Enlaces de interés


Enlaces en los que me he basado para redactar este artículo.



(Actualizado 30/06/2013)

No hay comentarios:

Publicar un comentario