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