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.