Análisis de peticiones en logs. [1/2]

Introducción


Últimamente me he interesado por la información que podemos obtener mediante los logs para utilizarla de forma proactiva. Por lo normal utilizamos los registros para detección de anomalías o desperfectos que afectan la operación de una aplicación, pero rara vez utilizamos toda la información que compone un log para proyectar un comportamiento u obtener el diagnóstico de cómo opera con "normalidad" nuestro sistema. 

En esta entrada de blog me gustaría realizar un análisis que responda a la pregunta ¿vale la pena invertir horas en la optimización de código en una aplicación web?. Para ello, nos enfocaremos en la correlación de los tiempos de respuesta (aka TR) y el número de peticiones que el sistema resuelve en un periodo de tiempo. Podríamos auxiliarnos de pruebas de estrés, sin embargo, algunas veces no disponemos de los ambientes necesarios, y solo nos queda hechar mano de los registros productivo, aún así, es decisión de cada quién cómo obtener la información requerida.
 
Los logs como el access de Apache es sumamente flexible para conocer cómo se desempeña la aplicación en cualquier ambiente. Una característica impportante es que puede ser en tiempo real o no, los registros (siempre que se resguarden) estarán disponibles para tratarlos.

El ejercicio fue realizado sobre un JBOSS 5.2, no obstante, puede funcionar con cualquier registro en formato log access. La configuración de tal formato de log en JBOSS sale del alcance de este documento. Haremos mucho uso de las herramientas de GNU/Linux, especialmente AWK; y algo de paquetería para presentación de datos.

Insumos


El formato luce más o menos como sigue:



Time Taken: 0.045 172.23.0.16 - - [11/Dec/2015:12:33:07 -0600] GET /APP/home.seam HTTP/1.1 200 18063 45
Time Taken: 0.017 172.23.105.153 - - [11/Dec/2015:12:33:09 -0600] GET /APP/home.seam HTTP/1.1 200 18063 17
Time Taken: 0.018 172.23.0.15 - - [11/Dec/2015:12:33:09 -0600] GET /APP/home.seam HTTP/1.1 200 18063 18



Nos interesa el tiempo de cada petición, la fecha, el método HTTP, el recurso en cuestión y por supuesto, el código de respuesta HTTP. Tenemos que ser claros en qué buscamos para darle sentido a la información. Para tales efectos, cree un formato como el que sigue.


Nombre del reporte/aplicación
Instancia 1 Instancia 2
Tiempo de respuesta Tiempo de respuesta
Promedio Máximo Mínimo Promedio Máximo Mínimo
0.0194362 10.715 0.014 0.021783 6.967 0.016
Peticiones Peticiones
Total Mayores a 2 segundos % Total Mayores a 2 segundos %
836752 39 0.0046608792 837338 37 0.0044187652
Listado de peticiones Listado de peticiones
TR Petición
TR Petición
2.075 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
3.213 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
2.371 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
6.967 /APP/APP/busqueda/BusquedaJerarquica.seam?cid=1853903
4.564 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
6.503 /APP/APP/busqueda/BusquedaDirecta.seam
2.447 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
4.656 /APP/APP/busqueda/BusquedaTematica.seam?cid=1854332
5.786 /APP/home.seam
2.09 /APP/APP/busqueda/BusquedaTematica.seam
2.702 /APP/APP/busqueda/BusquedaTematica.seam?cid=1860193
2.595 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js


Ahora bien, veámos cómo obtener cada uno de los datos. 

Juguemos con la línea de comandos


Parto de la idea que estarás utilizando tu poderoso GNU/Linux. Lo primero que buscaremos es el apartado de Tiempos de Respuesta. En este momento es bueno darle una leída a los apuntes de probabilidad y estadística.
 

Tiempo de respuesta
Promedio Máximo Mínimo
0.0194362 10.715 0.014


Promedio

cat logs_1/*.log | awk '{print $3,$9}' | awk '{sum +=$1} END {if (NR >0) print sum/NR}'


Máximo

cat logs_1/*.log | awk '{print $3,$10}' | sort -h

Mínimo

cat logs_1/*.log | awk '{print $3,$10}' | sort -r


Peticiones
Total Mayores a 2 segundos %
836752 39 0.0046608792


Total

 cat logs_1/*.log | awk '{print $3,$10}' | wc -l

Mayores a 2 segundos

cat logs_1/*.log | awk '{print $3,$10}' | awk '{ if ($1 > 2) print $2 }'

%

La fórmula en OpenOffice es: =(Mayores a 2 segundos *100)/Total de peticiones

Listado de peticiones
TR Petición
2.075 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js
2.371 /APP/a4j/g/3_3_1.SP3/org/richfaces/ui.pack.js

TR 

cat logs_1/*.log | awk '{print $3,$10}' | awk '{ if ($1 > 2) print $1 }'  

Petición

cat logs_1/*.log | awk '{print $3,$10}' | awk '{ if ($1 > 2) print $2 }'

Conclusión


Como se puede observar, los promedios en los tiempos de respuesta generales son muy buenos con respecto a los tiempos máximos y su frecuencia (datos de ejemplo). Por tanto, no vale la pena invertir horas en mejorar esos tiempos.

En la siguiente entrada abordaré la frecuencia de los tiempos máximos distinguiendo sobre el recurso y el porcentaje en que se presentan, de tal manera que dilucidemos si un recurso que es solicitado en pocos casos es su TR es alto con respecto al resto de sus solucitudes.


Comentarios

Entradas populares de este blog

Análisis de conexiones TIME_WAIT

Agregar un usuario a un grupo secundario

Desencriptar passwords AES y DES en WebLogic 10