Recebi uma ligação de alguém informando que eles estavam recebendo erros TNS-12519 em seu aplicativo. Com certeza, essas mensagens também estavam no arquivo listener.log.
TNS-12519: TNS:no appropriate service handler found
Para aqueles que não estão familiarizados com esse erro, normalmente significa uma de duas coisas. O nome do serviço não está registrado no listener ou o banco de dados atingiu o número máximo de processos. Para este último, o que acontece é que o Listener sabe que o banco de dados não pode aceitar nenhum novo processo, então ele tira o nome do serviço fora de serviço, por assim dizer. Um rápido “status lsnrctl” me mostra que o nome do serviço está registrado corretamente. Então deve ser o último. Em seguida, emito a seguinte consulta e confirmo minhas suspeitas.
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
Com certeza. Alcancei o máximo de processos, que está definido no meu SPFILE como 300. Aumentei o parâmetro para 600 e devolvi a instância. Atingimos o erro novamente com o dobro do número de processos. Obviamente, preciso me aprofundar mais nisso.
Para alguns antecedentes e para algo que será importante mais tarde, é importante saber que esse banco de dados suporta nossos esforços de teste automatizados. Temos um equipamento de teste que exercita nosso aplicativo de produção principal. Este conjunto de testes inicia o aplicativo, conecta-se ao banco de dados, pressiona alguns botões e seleciona alguns itens de menu e, em seguida, desconecta.
Examinei o arquivo listener.log para ver de onde vinham as solicitações de conexão. Essas solicitações vinham de um servidor de aplicativos desonesto, não de nosso conjunto de testes. Eu sabia que algo estava errado porque ainda não tínhamos iniciado o conjunto de testes e estávamos recebendo os erros. Corrigimos o servidor de aplicativos e não vi os erros retornarem. Em seguida, iniciamos o conjunto de testes e, algum tempo depois, os erros TNS-12519 retornaram. Hmmm... Achei que tinha encontrado o culpado. Mas vamos verificar a utilização do nosso processo.
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
Então, atualmente estou vendo 89 processos com uma utilização máxima de 157. Não estou nem perto do meu novo limite de 600. Então, o que dá? Demorei um pouco para descobrir qual era o problema. O nome do serviço está registrado corretamente e não estou nem perto do meu limite. MOS NOTE 552765.1 fala sobre como o Listener chega ao erro TNS-12519. Anteriormente, eu estava vendo a causa mais comum. Max PROCESSOS foi alcançado. Mas não desta vez Então o que dá?
Após investigação, encontrei minha resposta no log do ouvinte. Mas não era óbvio como uma grande mensagem de erro. A primeira ocorrência do erro TNS-12519 foi às 9h38. Eu procurei por “service_update” no log do ouvinte e vi essas 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
Observe que essa atualização de serviço ocorre regularmente às 9h17 e 9h18, mas o tempo entre as atualizações do serviço demora cada vez mais. Observe que houve 8 minutos e 38 segundos entre as atualizações de serviço no final (9:34 às 9:41). Por que isso é importante?
Este é um banco de dados Oracle 11.2.0.4. Para 11.2 e anteriores, o PMON é responsável pela limpeza após os processos e pela transmissão de informações ao Ouvinte. Na inicialização do banco de dados, o PMON tenta registrar os serviços com o Listener. Uma outra coisa que o PMON faz é informar ao Ouvinte quantos processos máximos podem ser atendidos. Nesse caso, o PMON informa ao ouvinte que pode ter até 600 processos. O PMON faz mais, mas para os propósitos desta discussão, isso é suficiente.
Uma parte importante a saber é que o Ouvinte nunca sabe quantos processos estão conectados no momento. Ele só sabe quantas solicitações de conexão ajudou a intermediar. O Ouvinte nunca sabe se os processos se desconectam do banco de dados. O service_update acima é onde o PMON está dizendo ao Listener quantos processos estão realmente sendo usados. Portanto, às 9:34:07, a atualização do serviço PMON informa ao Ouvinte que há 145 processos em uso. O Ouvinte agora está atualizado. Quando uma nova solicitação de conexão chega, o Ouvinte aumenta para 146 processos. Entre as atualizações do serviço, o Ouvinte desconhece totalmente que 1 ou mais processos podem ter sido encerrados, normal ou anormalmente. Ele continua incrementando sua contagem de processos até a próxima atualização de serviço, quando o Ouvinte obtém uma conta precisa de quantos processos são gerados.
Portanto, temos esse intervalo de 8,5 minutos entre as atualizações de serviço. Por que o PMON demorou tanto para retornar ao Listener? Bem, a pista para isso está no listener.log também. Retirei tudo do log antes do service_update das 9:34 e após a atualização do serviço das 9:41. A partir daí, foi fácil grep por “(CONNECT_DATA=” no que restava e canalizar para “wc -l” para obter uma contagem de linhas.
Durante esse intervalo de 8,5 minutos, tive mais de 450 novas solicitações de conexão! No entanto, a maioria dessas novas conexões foi encerrada, conforme evidenciado por V$RESOURCE_LIMIT, mostrando que eu tinha um máximo de 150. O PMON estava tão ocupado limpando o aplicativo saindo de suas conexões de banco de dados que teve um grande atraso antes de atualizar o Listener. No que diz respeito ao Listener, as 150 conexões atuais mais as 450 novas conexões significavam que ele atingiu seu limite de 600.
O PMON pode levar até 10 minutos para retornar ao Listener com sua próxima atualização de serviço. A limpeza após a saída das sessões da instância tem uma prioridade mais alta do que as atualizações de serviço para o Listener. Na marca de 10 minutos, o PMON torna a atualização do serviço a prioridade máxima se a atualização do serviço não tiver sido feita anteriormente nesse intervalo de tempo.
Lembre-se que este é um banco de dados para suportar testes automatizados. Temos que conviver com tantas operações de conexão/desconexão porque temos um robô automatizado testando nosso aplicativo de maneira rápida. Não queremos mudar a forma como o aplicativo funciona porque funciona muito bem quando executado por um único usuário. Nosso conjunto de testes automatizados está executando o aplicativo de forma diferente do que foi projetado para fazer. Mas queremos exercitar o aplicativo como está escrito para potencialmente expor bugs antes que as alterações de código atinjam a produção.
Por enquanto, aumentei o parâmetro PROCESSES para um valor que nunca alcançaremos. Tudo isso para que o Listener não consiga atingir o limite em seu contador interno. Quanto mais PROCESSOS, mais memória é necessária no SGA para suportar esse número maior. Mas este banco de dados pode lidar com isso.
Se alguém souber de uma maneira de fazer a atualização do serviço ocorrer em uma janela de 5 minutos, por favor me avise. Não há parâmetros documentados para controlar esse comportamento e também não consegui encontrar um não documentado.
Por fim, esse problema está em um dos meus bancos de dados 11.2.0.4. O Oracle 12c muda um pouco a arquitetura. O novo processo em segundo plano de registro de ouvinte (LREG) lida com o trabalho que o PMON costumava fazer. Ainda não tenho um sistema para testar, mas aposto que o LREG não terá o mesmo problema no 12c que o PMON está exibindo aqui no 11g, pois o LREG não terá que lidar com as tarefas de limpeza que o PMON faz. Nota MOS 1592184.1 mostra que LREG fará as atualizações de serviço.
Atualização:Desde que escrevi este artigo, tive a chance de atualizar o banco de dados para 12c com seu novo processo LREG. Com o LREG lidando com as atualizações de serviço do Listener, vimos o problema desaparecer. Mesmo durante períodos de intensa atividade de sessão, especificamente conectando e desconectando, o LREG fez atualizações regulares de serviço que o PMON não conseguiria realizar com tanta frequência.
