Histogramas de tiempos de ejecución SQL con AWK

Hace unos días tuve que analizar la performance de una aplicación java que usa Oracle y evaluar si el problema de lentitud estaba en las sentencias SQL ejecutadas. El escenario es:
 - el código no se puede modificar
 - la base de datos usada recibe cientos de sentencias por segundo de varias aplicaciones que vienen del mismo servidor.
 - en el mismo servidor de aplicaciones se ejecutan varias aplicaciones java similares a la que tiene problemas.

Como el problema es en producción, no había posibilidad de bajar el resto de las aplicaciones para dejar solo el tráfico de la problemática.

Así que la alternativa disponible fue habilitar un log de ejecución de sentencias en la aplicación.
Esto genera una entrada por cada ejecución en el archivo con este formato:

2013-09-09 14:38:44,066 [org.hibernate.SQL] Sentencia

No sabemos en qué momento se escribe la entrada en el log. Puede ser antes o después de ejecutar la sentencia. Pero lo que sí sabemos es que el tiempo de ejecución es como máximo el tiempo entre dos entradas consecutivas. Así que como una aproximación sirve para tener una idea de por donde puede venir el problema.

Obtener datos útiles de archivos de log con sentencias SQL es una alternativa muy conocida y bien aprovechada en MySQL con utilitarios como pt-query-digest. Sin intentar imitarlo, me alcanza con ver los tiempos de ejecución de las sentencias, cosa que se puede obtener con un simple script AWK tomando el tiempo transcurrido entre dos entradas consecutivas. Por ejemplo, para ver las que demoraron más de un segundo:

oracle@oraculo:~> awk '{split($3,a,":"); sec=60*(60*a[1]+a[2])+a[3]; if(b!=0 && (sec-b)>1){ print $3 " - " sec - b; }; b=sec}' /tmp/pp.txt
    14:38:49,899 - 5,015
    14:38:51,995 - 2,094
    14:43:46,037 - 2,067
    14:43:51,054 - 5,015
    14:43:56,072 - 5,015

Así puedo ir al log y ver cuales fueron esas sentencias para después analizar si realmente tienen buenos planes de ejecución.

Limpié del archivo entradas iniciales antes de empezar la ejecución de sentencias, y algunas entradas finales, mirando con un editor los números de línea (vi y g es lo más simple). Así nos quedamos con las líneas 6821 a 74572:

oracle@oraculo:~> head -n 74572 myjavaapp.2013091112.log | tail -n +6821 > /tmp/pp.txt

Las sentencias SQL incluidas en este log son:

oracle@oraculo:~> grep -ic insert /tmp/pp.txt
    507
oracle@oraculo:~> grep -ic delete /tmp/pp.txt
    0
oracle@oraculo:~> grep -ic update /tmp/pp.txt
    524
oracle@oraculo:~> grep -ic select /tmp/pp.txt
    2254

Para tener una visión más clara del tiempo de ejecución de las sentencias, armo histogramas de tiempos de ejecución, redondeando a 0,1 segundo (tiempos más chicos no me interesa optimizar). El formato de esta salida es: tiempo de ejecución en segundos y cantidad de sentencias.

oracle@oraculo:~> awk 'BEGIN {b=0;} { split($3,a,":"); sec=60*(60*a[1]+a[2])+a[3]; if(b!=0){ n[int((sec-b)*10+.5)/10]++}; b=sec} END {for (i in n) print i,n[i]}' /tmp/pp2.txt | sort -n
   
    0 2268
    0,1 161
    0,2 421
    0,3 207
    0,4 90
    0,5 68
    0,6 50
    0,7 11
    0,8 1
    0,9 2
    2,1 2
    5 3

Se puede ver con claridad que la mayoría de las sentencias se resuelven en menos de 0,4 segundos, lo que indica con claridad que la base de datos no está teniendo problemas, y se debe analizar el código de la aplicación en busca de más pistas de la lentitud observada.

Espero les sea útil.
Un saludo.