segunda-feira, 18 de agosto de 2008

Detectando Connection Leaks no JBoss - Parte 1

Quando o usuário te liga falando as famosas frases:
- "alguma coisa está acontecendo!" ou
- "hummm, a aplicação está estranha!" ou ainda
- "esse JBoss NÃO FUNCIONA! não fecha minhas conexões!" ... hummm "JBoss não fecha suas conexões"? Ok, o JBoss fecha conexões idle (timeout default de 15 minutos), mas até lá já estourou o pool, e olhando o log você verá as mensagens:

15:58:48,931 ERROR [STDERR] org.jboss.util.NestedSQLException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ); - nested throwable: (javax.resource.ResourceException: No ManagedConnections available within configured blocking timeout ( 30000 [ms] ))


E até que o JBoss é gente fina, ao fechar alguma conexão aberta avisa educadamente para você fazer isso:

16:03:19,135 INFO  [CachedConnectionManager] Closing a connection for you.  Please close them yourself: org.jboss.resource.adapter.jdbc.WrappedConnection@121dcac java.lang.Throwable: STACKTRACE


Mas afinal, em alguns casos a aplicação não loga em modo debug onde está abrindo/fechando as conexões, e em aplicações grandes, ou sem padronização, a tarefa de detectar um gargalo destes torna-se tarefa complicada. Então, como detectar onde está ocorrendo a leak?

Este post tem como objetivo mostrar algumas técnicas para isolar os pontos e atacá-los.

Para fazer esta prova de conceito, criei uma classe que tenta abrir 30 conexões em pool de no máximo 20, fazendo um loop e armazenando-as em um Map.

public class ConnectionLeak {

private static Logger log = Logger.getLogger(ConnectionLeak.class);

private static Map m = new HashMap();

public static void action() {
for (int i = 0; i < 30; i++) {
try {
Context ic = new InitialContext();
DataSource ds = (DataSource) ic.lookup("java:DefaultDS");
Connection c = ds.getConnection();
log.info("Obtendo conexao: " + c + " loop: " + i);
m.put(i, c);
} catch (NamingException e) {
e.printStackTrace();
} catch (SQLException e) {
e.printStackTrace();
}
}
}
}



Estou logando um toString de cada conexão após abri-la:

16:31:33,444 INFO  [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@41f871 loop: 0
16:31:33,445 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@11df416 loop: 1
16:31:33,446 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@183d60d loop: 2
16:31:33,447 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@5a1e6b loop: 3
16:31:33,447 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@83198c loop: 4
16:31:33,448 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@1025f9f loop: 5
16:31:33,449 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@d3e83f loop: 6
16:31:33,450 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@3492fc loop: 7
16:31:33,450 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@19e0994 loop: 8
16:31:33,451 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@86f847 loop: 9
16:31:33,452 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@1162ab9 loop: 10
16:31:33,453 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@4eda4a loop: 11
16:31:33,465 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@1eab16b loop: 12
16:31:33,466 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@126099c loop: 13
16:31:33,467 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@40eca3 loop: 14
16:31:33,468 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@6fe350 loop: 15
16:31:33,469 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@1b4b415 loop: 16
16:31:33,469 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@9addef loop: 17
16:31:33,470 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@1609812 loop: 18
16:31:33,471 INFO [ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@9fe953 loop: 19

1. Monitore as conexões ativas do seu Datasource
Existem boas ferramentas para realizar uma monitoração efetiva do seu pool de conexões, entre elas está o JON - JBoss Operations Network que além de guardar histórico podendo ser filtrado em horas, dias, meses também gera alertas com ações remediativas e envio de e-mails ou traps SNMP. Porém o JBoss AS disponibiliza o Web Console e o JMX Console que, apesar de não serem tão completos como o JON, podem ser utilizados para um diagnóstico inicial. Abaixo um Screenshot do meu Connection Leak simulado:




2. Habilite o log abaixo no jboss-log4j.xml:

<!-- Show the evolution of the DataSource pool in the logs [inUse/Available/Max]-->
<category name="org.jboss.resource.connectionmanager.JBossManagedConnectionPool">
<priority value="TRACE" class="org.jboss.logging.XLevel"/>
</category>


2008-08-18 16:58:04,460 INFO  [org.jboss.ConnectionLeak] Obtendo conexao: org.jboss.resource.adapter.jdbc.WrappedConnection@4f12c2 loop: 1
2008-08-18 16:58:04,461 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] supplying ManagedConnection from pool: org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@15092c0[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@d2883b handles=0 lastUse=1219089352148 permit=false trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$PoolBySubject@554189 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@141a32f xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1ee1775 txSync=null]
2008-08-18 16:58:04,462 TRACE [org.jboss.resource.connectionmanager.JBossManagedConnectionPool] Got connection from pool org.jboss.resource.connectionmanager.TxConnectionManager$TxConnectionEventListener@15092c0[state=NORMAL mc=org.jboss.resource.adapter.jdbc.local.LocalManagedConnection@d2883b handles=0 lastUse=1219089352148 permit=true trackByTx=false mcp=org.jboss.resource.connectionmanager.JBossManagedConnectionPool$PoolBySubject@554189 context=org.jboss.resource.connectionmanager.InternalManagedConnectionPool@141a32f xaResource=org.jboss.resource.connectionmanager.TxConnectionManager$LocalXAResource@1ee1775 txSync=null] [InUse/Available/Max]: [3/17/20]


3. Verifique as conexões em cache
O MBean CachedConnectionManager possui o método listInUseConnections() que permite a verificação das conexões em uso. Pode te dar alguma pista:



to be continued...

6 comentários:

Alexandre Porcelli disse...

E aí Bruno, blz!?

Excelente post... mas será que ainda hoje alguém esquece de fechar conexões? hahahahah ;)

[]s
Alexandre Porcelli

rafaeltuelho disse...

Com ctz Alexandre. Tem cada app monstrinho que agente encontra por aí... :)

Outra forma de encontrar onde a conexão está sendo deixada aberta é habilitando um trace no próprio DataSource usado pela App.

Para isso adicine a seguinte propriedade dentro do seu -ds.xml:

[track-statements]true[/track-statements]

Com isso o JBoss começará a logar algo do tipo:

WARN [org.jboss.resource.adapter.jdbc.WrappedConnection] Closing a statement you left open, please do your own housekeeping
java.lang.Throwable: STACKTRACE
at org.jboss.resource.adapter.jdbc.WrappedConnection.registerStatement(WrappedConnection.java:562)
at org.jboss.resource.adapter.jdbc.WrappedStatement.init(WrappedStatement.java:40)
at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.init(WrappedPreparedStatement.java:41)
at org.jboss.resource.adapter.jdbc.WrappedConnection.prepareStatement(WrappedConnection.java:172)


isso é equivalente ao resultado do método listInUseConnections() do MBean CachedConnectionManager.

falow!

Bruno Rossetto Machado disse...

O track-statements é apenas para Statements, PreparedStatements e ResultSets.
Mais informações em:
http://www.jboss.org/community/docs/DOC-9255

Halisson disse...

Olá
O meu problema é o seguinte: eu tenho uma aplicação bem antiga que não fecha as conexões (umas 350 jsp).
Para minimizar esse problema, eu gostaria de habilitar o meu jboss para fechar automaticamente as conexões até que a equipe aqui consiga corrigir todas as páginas.

Quais configurações eu tenho que realizar no jboss para habilitar essa funcionalidade? Pois o jboss não está fazendo isso.
O jboss que roda aqui é a vesão 3.2.5

Paulo Silveira disse...

valeu bruno! me ajudou 2 anos depois a achar a categoria do log4j pra isso.

Bruno Rossetto Machado disse...

Halisson, o JBoss fecha apenas conexões idle conforme seu "idle-timeout". Tente utilizar uma ferramenta de análise estática, como o FindBugs por exemplo, para encontrar os pontos da aplicação que não fecham as conexões e feche-as manualmente. É de responsabilidade da aplicação abrir e fechar as conexões com o App. Server (qualquer um) e é de responsabilidade do App. Server abrir, fechar e gerenciar conexões TCP com o Banco de Dados.