Recibí una llamada de alguien que estaba recibiendo errores TNS-12519 en su aplicación. Efectivamente, esos mensajes también estaban en el archivo listener.log.
TNS-12519: TNS:no appropriate service handler found
Para aquellos que no están familiarizados con este error, generalmente significa una de dos cosas. El nombre del servicio no está registrado con el agente de escucha o la base de datos ha alcanzado su número máximo de procesos. Para este último, lo que sucede es que el Listener sabe que la base de datos no puede aceptar ningún proceso nuevo, por lo que toma el nombre del servicio fuera de servicio, por así decirlo. Un rápido "estado de lsnrctl" me muestra que el nombre del servicio está registrado correctamente. Así que debe ser esto último. Luego emito la siguiente consulta y confirmo mis sospechas.
SQL> select resource_name,current_utilization,max_utilization 2 from v$resource_limit where resource_name='processes';
RESOURCE_NAME CURRENT_UTILIZATION MAX_UTILIZATION --------------- ------------------- --------------- processes 299 300
Bastante seguro. Alcancé el máximo de procesos, que se define en mi SPFILE como 300. Aumenté el parámetro a 600 y reboté la instancia. Volvemos a dar el error con el doble de procesos. Obviamente necesito profundizar más en esto.
Para algunos antecedentes, y para algo que será importante más adelante, es importante saber que esta base de datos respalda nuestros esfuerzos de prueba automatizados. Tenemos un arnés de prueba que ejercita nuestra aplicación de producción principal. Este conjunto de pruebas inicia la aplicación, se conecta a la base de datos, presiona algunos botones y selecciona algunos elementos del menú y luego se desconecta.
Examiné el archivo listener.log para ver de dónde venían las solicitudes de conexión. Estas solicitudes provenían de un servidor de aplicaciones no autorizado, no de nuestro conjunto de pruebas. Sabía que algo andaba mal porque aún no habíamos iniciado el conjunto de pruebas y recibíamos errores. Arreglamos el servidor de aplicaciones y no vi que regresaran los errores. Luego encendimos el conjunto de pruebas y, algún tiempo después, volvieron los errores TNS-12519. Hmmm... Pensé que había encontrado al culpable. Pero revisemos la utilización de nuestro proceso.
SQL> select resource_name,current_utilization,max_utilization 2 from v$resource_limit where resource_name='processes';
RESOURCE_NAME CURRENT_UTILIZATION MAX_UTILIZATION --------------- ------------------- --------------- processes 89 157
Así que actualmente estoy viendo 89 procesos con una utilización máxima de 157. No estoy ni cerca de mi nuevo límite de 600. Entonces, ¿qué sucede? Me tomó un tiempo averiguar cuál era el problema. El nombre del servicio está registrado correctamente y no estoy ni cerca de mi límite. MOS NOTE 552765.1 habla sobre cómo el oyente llega al error TNS-12519. Anteriormente, estaba viendo la causa más común. Se había llegado al máximo de PROCESOS. Pero no esta vez Entonces, ¿qué da?
Después de investigar, encontré mi respuesta en el registro del oyente. Pero no era tan obvio como un gran mensaje de error. La primera aparición del error TNS-12519 fue a las 9:38 am. Busqué "service_update" en el registro del oyente y vi estas entradas.
25-JUN-2015 09:17:08 * service_update * orcl * 0 25-JUN-2015 09:17:26 * service_update * orcl * 0 25-JUN-2015 09:17:29 * service_update * orcl * 0 25-JUN-2015 09:17:44 * service_update * orcl * 0 25-JUN-2015 09:17:50 * service_update * orcl * 0 25-JUN-2015 09:17:53 * service_update * orcl * 0 25-JUN-2015 09:18:56 * service_update * orcl * 0 25-JUN-2015 09:18:59 * service_update * orcl * 0 25-JUN-2015 09:19:50 * service_update * orcl * 0 25-JUN-2015 09:20:11 * service_update * orcl * 0 25-JUN-2015 09:21:27 * service_update * orcl * 0 25-JUN-2015 09:22:09 * service_update * orcl * 0 25-JUN-2015 09:24:05 * service_update * orcl * 0 25-JUN-2015 09:27:53 * service_update * orcl * 0 25-JUN-2015 09:29:32 * service_update * orcl * 0 25-JUN-2015 09:34:07 * service_update * orcl * 0 25-JUN-2015 09:41:45 * service_update * orcl * 0
Tenga en cuenta que esta actualización del servicio ocurre regularmente a las 9:17 y 9:18, pero el tiempo entre las actualizaciones del servicio toma más y más tiempo. Observe que hubo 8 minutos y 38 segundos entre las actualizaciones del servicio al final (9:34 a 9:41). ¿Por qué es esto importante?
Esta es una base de datos Oracle 11.2.0.4. Para 11.2 y versiones anteriores, PMON es responsable de limpiar los procesos posteriores y de pasar información al Listener. En el inicio de la base de datos, PMON intenta registrar los servicios con el Listener. Otra cosa que hace PMON es decirle al oyente cuántos procesos máximos se pueden atender. En este caso, PMON le dice al oyente que puede tener hasta 600 procesos. PMON hace más, pero para los propósitos de esta discusión, eso es suficiente.
Una pieza importante que debe saber es que el Oyente nunca sabe cuántos procesos están conectados actualmente. Solo sabe cuántas solicitudes de conexión ha ayudado a negociar. El Listener nunca sabe si los procesos se desconectan de la base de datos. El service_update anterior es donde PMON le dice al Listener cuántos procesos se están utilizando realmente. Entonces, a las 9:34:07, la actualización del servicio PMON le dice al Listener que hay 145 procesos en uso. El Oyente ahora está actualizado. Cuando llega una nueva solicitud de conexión, el Listener incrementa esto a 146 procesos. Entre las actualizaciones del servicio, el Listener ignora por completo que 1 o más procesos pueden haber terminado, normal o anormalmente. Sigue incrementando su conteo de procesos hasta la próxima actualización del servicio cuando el Oyente obtiene una cuenta precisa de cuántos procesos se generaron.
Así que tenemos esa brecha de 8,5 minutos entre las actualizaciones del servicio. ¿Por qué PMON tardó tanto en volver al Oyente? Bueno, la pista para eso también está en listener.log. Eliminé todo del registro antes de la actualización del servicio a las 9:34 y después de la actualización del servicio a las 9:41. A partir de ahí, fue fácil buscar "(CONNECT_DATA=" en lo que quedaba y canalizar a "wc -l" para obtener un recuento de líneas.
¡Durante este intervalo de 8,5 minutos, tuve más de 450 nuevas solicitudes de conexión! Sin embargo, la mayoría de esas conexiones nuevas terminaron, como lo demuestra V$RESOURCE_LIMIT, que me mostró que tenía un máximo de 150. PMON estaba tan ocupado limpiando las conexiones de la base de datos de la aplicación que tuvo un gran retraso antes de actualizar el Listener. En lo que respecta al Oyente, las 150 conexiones actuales más las 450 conexiones nuevas significaron que alcanzó su límite de 600.
PMON puede tardar hasta 10 minutos en volver al Listener con su próxima actualización de servicio. Limpiar después de que las sesiones salen de la instancia tiene una prioridad más alta que las actualizaciones de servicio para el Listener. En la marca de 10 minutos, PMON hace que la actualización del servicio sea la máxima prioridad si la actualización del servicio no se había realizado previamente en ese intervalo de tiempo.
Recuerde que esta es una base de datos para soportar pruebas automatizadas. Tenemos que vivir con tantas operaciones de conexión/desconexión porque tenemos un robot automatizado que prueba nuestra aplicación de forma rápida. No queremos cambiar el funcionamiento de la aplicación porque funciona muy bien cuando la ejecuta un solo usuario. Nuestro conjunto de pruebas automatizadas está ejecutando la aplicación de manera diferente a la que fue diseñada. Pero queremos ejercitar la aplicación tal como está escrita para exponer posibles errores antes de que los cambios en el código lleguen a la producción.
Por ahora, aumenté el parámetro PROCESOS a un valor que nunca alcanzaremos. Todo esto para que el Listener no pueda llegar al límite en su contador interno. Cuantos más PROCESOS, más memoria se necesita en el SGA para admitir ese número más alto. Pero esta base de datos puede manejarlo.
Si alguien conoce una forma de hacer que la actualización del servicio se realice en una ventana de 5 minutos, hágamelo saber. No hay ningún parámetro documentado para controlar este comportamiento y tampoco he podido encontrar uno sin documentar.
Por último, este problema está en una de mis bases de datos 11.2.0.4. Oracle 12c cambia un poco la arquitectura. El nuevo proceso en segundo plano del registro de oyentes (LREG) maneja el trabajo que solía hacer PMON. Todavía no tengo un sistema para probar, pero apuesto a que LREG no tendrá el mismo problema en 12c que PMON está exhibiendo aquí en 11g, ya que LREG no tendrá que encargarse de las tareas de limpieza que tiene PMON. La nota MOS 1592184.1 muestra que LREG realizará las actualizaciones del servicio.
Actualización:desde que escribí este artículo, tuve la oportunidad de actualizar la base de datos a 12c con su nuevo proceso LREG. Con LREG manejando las actualizaciones del servicio de Listener, vimos que el problema desaparecía. Incluso durante los momentos de gran actividad de la sesión, específicamente la conexión y la desconexión, LREG realizó actualizaciones periódicas del servicio que PMON no habría podido realizar con tanta frecuencia.
