- 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
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.
