Análisis Gráfico de Excepciones Java en Bitácoras (Logs)

En ocasiones nos va tocar analizar qué está sucendiendo con nuestra aplicación en vivo porque aparentemente estamos teniendo "muchas" excepciones. Entrecomillo "muchas" porque como desarrolladores o encargados del monitoreo de la aplicación, alguien puede reportarnos que está viendo muchas excepciones en las bitácoras (logs) pero en realidad no sabemos si son muchas hasta que las contemos y veamos cuál es el promedio normal de apariciones de cierta excepción; en otras palabras, ver cuál es la tendencia de cierto tipo de excepciones. Si tenemos que analizar bitácoras enormes donde el comando buscar del editor de texto ("CTRL + F") no es suficiente para tener una perspectiva a gran escala, es entonces donde tenemos que atacar el problema de una forma más automatizada.

Quiero compartir en este artículo la fórmula que he utilizado en el pasado para analizar grandes cantidades de excepciones en grandes extenciones de bitácoras. Para generar el gráfico que vamos analizar uso un script de Perl para formatear los datos de una manera resumida y adecuada para luego procesarlos en una hoja de cálculo. En mi caso uso Calc de Open Office pero una hoja de Excel podría ser usada de igual manera.

El siguiente script de Perl extrae el nombre de la excepción y la fecha con la hora en que fue lanzada, y salva estos dos datos en dos columnas separadas por el carácter "~":

#!/usr/local/bin/perl

my $dir = $ARGV[0];

print "\n\n\t\tReading directory: " . $dir . " ...\n\n";
opendir(DIR, $dir);

my @files = readdir(DIR);
my $output = $dir."_results.txt";
closedir(DIR);

open (RESULTS, '>'.$output);
print RESULTS "date~exception\n";
$exception_counter = 0;

foreach $file( @files){
unless ( ($file eq ".") || ($file eq "..") ) {
my $total_size_read = 0;
my $file_path = $dir . '\\' . $file;
my $filesize;
{
use strict;
use warnings;
$filesize = -s $file_path ;
$filesize = $filesize / 1000; #Kbytes
}

print "\nReading file " .$file_path . "(" . $filesize . " kb)\n";
open (LOG, $file_path) || die "couldn't open the file!"; 

$line_number = 1;

while ($record = ) {

if ($record =~ m/([a-zA-Z1-9\.]*Exception)+/) {
$exception_description = $1;

if ($record =~ m/(((\d{4})-(\d{2})-(\d{2})\s(\d{2}))(:\d{2}:\d{2}))/) {    
 $year= $3;
 $month=$4;
 $day=$5;
 $hour=$6;     
 print RESULTS  $year . "-". $month . "-" . $day . " "  .  $hour . ":00~" . $exception_description ."\n" ;
 $exception_counter++; 
}
} 

$line_number++;
if ($line_number % 1000 eq 0) {
my $progress = sprintf("%.2f",(($total_size_read /1000) / $filesize) * 100);
print "\rTotal lines read: " . $line_number . " | Exceptions found: " . $exception_counter . " | Progress:" . $progress . "%";

}
{
use bytes;
my $byte_size = length($record);
$total_size_read = $total_size_read + $byte_size;
}
}

close(LOG);
}
}

close (RESULTS);

No voy a detallar mucho la lógica del script la cual de todas maneras es bastante simple. Recibe como argumento el nombre de un directorio y procesa todos los archivos que hayan dentro de él para extraer las aparaciones de excepciones de cada archivo.



El resultado final del script es un archivo con el siguiente formato:

date~exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~java.lang.NullPointerException
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 21:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~Exception
2009-08-16 22:00~java.lang.NullPointerException

En este punto abrimos Calc de Open Office, seleccionamos los resultados del script, los copiamos y pegamos en la hoja de cálculo. Automáticamente se abrirá una caja de dialogo como la siguiente en la cual marcamos la caja de otros ("others") y escribimos el carácter de "raba de chancha" para separar los datos en dos columnas.

Una vez hecho esto es recomendable ordenar los datos de manera ascendente acorde con la columna de fecha para tener una secuencia cronológica de las excepciones. Seleccionamos las dos columnas excepto por la primera fila y usamos la opción de ordenamiento (Data->Sort...).



Seguidamente usamos, en mi opinión, una de las herramientas más poderosas de una hoja de cálculo: el DataPilot o Tabla Pivot en lenguaje Excel. El DataPilot nos permite agrupar datos de distintas columnas y contar o sumar el número de apariciones de acuerdo a las categorias que definimos con las columnas que seleccionamos. Seleccionamos las dos columnas, Data->DataPilot->Start...


En el diálogo que se abre arrastramos la caja "date" en los campos de columna, y la caja "exception" en los campos de fila. Tomamos nuevamente la caja "exception" y la arrastramos en el medio y damos clic en opciones. La opción por defecto es "Sum"; la cambiamos por "Count" para contar el número de apariciones por fecha y excepción. Más abajo hay otras opciones útiles que debemos usar:

1. Resultados en una nueva hoja: "Results to - new sheet -".
   
2. Ignorar filas vacias: "Ignore empty rows".
   

A partir de este momento podemos comenzar a analizar la línea cronológica de excepciones, o verificar un punto discreto de nuestra línea de tiempo si sabemos de antemano que algo sucedió en determinado día u hora. Para completar nuestro análisis vamos a generar un gráfico con la tabla que recien generamos.

Seleccionamos el rango de nuestra tabla para adelantarnos en uno de los pasos en la creación de nuestro gráfico. Buscamos el icono de gráfico ("chart") y lo presionamos.


1. Lo primero que tenemos que hacer es seleccionar el tipo de gráfico. En este caso uso el de puntos y líneas:


2. Dado que ya había seleccionado el rango de datos, la primera caja ya contiene nuestra selección previa. Debemos seleccionar la opción de series de datos en filas ("data series in rows") y chequear las dos opciones de primera fila y columna como etiquetas.


3. En las series de datos no hay mucho que modificar. Podemos quitar la serie de "Total Result " si nos causa algún ruido en nuestro análisis. Siempre podemos regresar a modificar esta sección después de generado el gráfico.

4. En elementos del gráfico no cambiamos nada relevante. En mi caso me gusta cambiar la posición de las leyendas del eje Y, o sea cada uno de los nombre de excepción, para situarlas arriba del gráfico, de otra manera quedan posicionados a la derecha y resulta a veces que son demasiadas leyendas con nombres extensos que acortan el área del gráfico que nos interesa analizar.

Generamos finalmente nuestro gráfico el cual como podrán notar, sale un poco desordenado por la gran cantidad de elementos en el eje X. Para solucionar esto podemos editar el gráfico en las propiedades del eje X.

Clic derecho al gráfico -> Edit -> Clic derecho al eje X -> Object Properties
Vamos a la sección de etiqueta ("label") y rotamos el texto desde su posición de 0° hasta algún nivel de inclinación que nos permita apreciar mejor nuestro gráfico. En mi caso uso 45°. 90° sería también útil para no escalar tanto nuestro gráfico.

Finalmente quedamos con un producto final del cual podemos sacar algunas conclusiones interesantes. Por ejemplo podemos ver una tendencia hasta cierto punto normal de número de excepciones desde el periodo del 14 Agosto pero después súbitamente el número de excepciones de NullPointerException se disparan el 17 del mismo mes. ¿Habrá sucedido algún evento especial en esa fecha?


Como ven el gráfico a escala nos permite iniciar nuestro análisis de manera más focalizada sin comenzar a dar tumbos a ciegas. De aquí en adelante nos tocará tomar otros pasos para continuar la investigación, pero te aseguro que si presentas en una reunión a tu jefe y/0 cliente un gráfico de este tipo, vas a lucir mucho más profesional que simplemente decir:

-"Tenemos muchas excepciones de NullPointer"