viernes, octubre 14, 2011

Deadlock detected al obtener las conexiones JNDI en un WAS 7.0.0.13


Hace unos días dejamos en producción una aplicación que migramos de websphere 6.1 a websphere 7. (IBM WAS 7).


En principio vale mencionar que no hay nada transparente ni "migrable" entre lo que hicimos con RAD6 para que funcione en WAS7, RAD8 no soporta SDO y tuvimos que migrar "a mano" muchas cosas re-certificando toda la aplicacion, pero eso es otro tema que no comentaré a detalle.

Lo que sí quería mencionar es un error un poco raro que tuvimos luego de la salida en producción. La aplicación en testing y desarrollo funcionaba bien, pero al estar en producción empezó a dar algunos problemas, en momentos de stress de repente el WAS se colgaba completo, inclusive dejaba de responder la consola.


Revisando el SystemOut y el SystemErr empezaron a aparecer algunos errores en la clase que obtenía la conexión a la base de datos, pero no encontramos nada que nos diera una pista de que podría dar problemas.
Vale la pena comentar que como desarrollo no teníamos acceso a los servidores por lo que el proceso de resolución fué muy tortuoso y lento.

Lo primero que verificamos, lo obvio, fué pensar que había un leak de conexiones. Revisamos el systemout buscando cualquier error que nos diera una pista del error y no encontramos nada. Recibimos algunos reportes de los administradores donde se miraba que la caída era un problema que sucedía en poco tiempo (<2 minutos). No era un proceso de degradación poco a poco sino que era una caída casi inmediata.


Sospechabamos de algún reporte o algún proceso donde por algún error hubiera algún tipo de loop infinito donde no se cerraran las conexiones. No encontramos nada.
Luego encontramos en los reportes que el total de threads que tenía configurado el WAS se ocupaban al 100%, nuestra teoría en este momento era que el leak de conexiones hacía que las peticiones se encolaran en el jndi y ocuparan threads y esto hiciera que el server se cayera.
Exploramos algunas alternativas sobre la configuración del WAS, subimos los threads disponibles, pusimos un parámetro en el JNDI para que si no recibía la conexión en 5seg que diera exception. Esto aunque sabíamos que no corregía el error nos daba lapsos más grande
s entre una caída y otra y en lugar de que el was se quedara freeze empezaría a dar error de aplicación donde podríamos encontrar la raíz del problema. Hicimos los cambios y nada. Aunque subieramos los threads igual se ocupaban todos y por alguna extraña razón no respetaba el parametro que pusimos para que diera exception si no obtenía la conexión.

Un poco desesperados peinamos el código (una aplicación grande) y revisamos todas las conexiones para incluir un best practice en cuanto a cierre de las conexiones. Probamos de nuevo y nada. Es más, los errores ocurrian más seguido.

Luego un día estando en audio con los administradores de bdd y con los administradores de WAS, tuvimos una caída. Fué entonces cuando logramos tener al fin el error en las manos. Vimos las propiedades del pool y ... sorpresa! el uso del pool estaba al 50% de su capacidad... No podía ser un connection leak si solo teníamos 50% de las conexiones usadas. Ya habíamos limpiado todos los system.out.println y el systemout estaba sin ningun tema. el systemerr tampoco tenía nada. Generaron un dump de la caída y ahí vimos entonces el error.
buscando en el javacore encontramos un Deadlock detected.
Al analizar más a detalle el lugar donde se reporta el error, vimos que el metodo que muestra la traza es un metodo del pool y que no es parte del aplicativo sino parte del driver jndi de websphere.

Buscando un poco más sobre este tema encontramos algunos casos similares al nuestro:
Y encontramos luego un problema del driver de jdbc, "PK69110: THE SERVANT ABENDS CAUSED BY HUNG THREADS IN JDBC DRIVER".
Este bug tiene afectación en la versión de WAS que usamos http://www-01.ibm.com/support/docview.wss?uid=swg1PK69110&wv=1

La versión de WAS que usamos es la 7.0.0.13, encontramos entonces el problema definitivo. Un parámetro useRRASetEquals en la configuración custom del datasource.

se hizo la prueba, se pasó a producción y luego de varias semanas tratando de encontrar el problema en nuestra aplicación vimos que es un bug de WAS.

El bug era este: Cuando yo le pido una conexión al pool, el jndi usa un objeto con las conexiones utilizadas. Este objeto es compartido. Por alguna razón al tratar de reservar una conexión en el pool el objeto se quedaba tomado por otro thread y causaba un deadlock de threads. Todo esto a nivel de los javas que hacen el pool. mientras mas usuarios trataban de obtener la conexión habían más threads que se encolaban hasta que se acababan los threads del was. Luego ni siquiera la consola de WAS funcionaba y era el freeze. Como era el objeto que reservaba la conexión el error se daba antes de que el parametro de timeout que configuramos entrara y por eso no se tomaba en cuenta.
La moraleja:
hay que leer los javacore cuando hay servers colgados... aunque sean de 500MB.

saludos!