Vazamento de memória e de conexões

Descrevo aqui a minha aventura junto com diversos desenvolvedores da Caelum: Cauê Guerra, Filipe Sabella, Anderson Leite, Pedro Mariano e o Pedro Matiello para resolver um grande problema que ocorria em um dos nossos projetos.

Assim como quando um avião cai, não é um bug que gera um grande problema, mas sim uma série de fatores que contribuem para a dificuldade na hora de encontrar complicações estruturais de um projeto.

Vamos aos fatos, que incluem bugs e vazamentos em bibliotecas famosas, profiling e open call hierarchy de eclipse.

Sintoma: o servidor web parava de responder para qualquer página, exceto a tela de login

Nesse caso, o servidor entrava na tela de login mas ao tentar submete-la ou acessar qualquer outra funcionalidade o browser não recebia resposta alguma do servidor web.

A primeira coisa a pensar era que o processador estaria a 100%, que é o caso comum em laços infinitos ou threads gulosas além da conta. Mas um comando rápido no servidor (top) mostrava que o processador estava a 0%. Claro, se estivesse a 100%, teríamos duas opções:

  1. rodar o profiler e detectar o método que estaria consumindo 100% do cpu
  2. imprimir todas as threads do sistema (com Thread.métodos estáticos) e ver o stack trace de cada uma delas… detectaríamos o mesmo ponto.

Mas como nosso problema não era esse, uma possível causa levantada pelo Rafael Cosentino foi de que poderia haver algum deadlock, travando todas as requisições. Pensando na dificuldade de detectar tal falha, e acreditando que o problema estava relacionado com o consumo de memóriaapesar de não haver OutOfMemoryErrors), decidimos usar o JProfiler.

O primeiro passo foi rodar o profiler no Stella Boleto para verificar se ele estava com algum leak, pois sabíamos que o mesmo consome uma memória razoável durante o processo de geração do boleto, devido a imagem de background de alta resolução ser carregada num BufferedImage. Memória a qual deveria ser liberada. Ao rodar o profiler, o Caue Guerra, executou diversas threads em paralelo com invocações complexas do Stella Boletos. Durante e após as execuções, não houve memory leak algum, e o garbage collector consumia os objetos corretamente.

Sem nenhum ponto especial, teríamos que fazer o profiling da aplicação inteira.

Foram várias tentativas com profiling remoto offline, o código java invocava a api de profiling para depois analisarmos os resultados em nossas máquinas, porém um bug do JProfiler com o Apache Tomcat 6.0.16 inviabilizou tal análise. Fomos então rodar a aplicação no Jetty 7 (apontando para a mesma configuração do tomcat) sem que nenhum usuário da aplicação live notasse a mudança: uma migração transparente de servlet containers executada com êxito, assim como ocorreu no GUJ.

Em paralelo, o Tomcat foi atualizado para 6.0.18, que funciona com a última versão do JProfiler corretamente e levantamos o mesmo com apenas 64 megas de ram (para estressar o garbage collector mais frequentemente). Rodando o Tomcat em outra porta, mas acessando o mesmo banco de produção, permitiu que testássemos junto ao cliente exatamente as funcionalidade que ele julgava “lentas”.

Em algum ponto durante o uso do JProfiler, o mesmo indicou que não havia nenhum deadlock de threads, bastando para ele verificar se existem threads esperando por monitores de maneira cruzadas.

Primeiro sinal de leak: Executamos algumas tarefas no sistema e vimos que o número de objetos crescia de maneira adequada, porém, ao rodar o GC, alguns objetos ficavam para trás… objetos que são entidades do projeto! É comum o número de Strings, arrays de char e de bytes crescerem, mas entidades do nosso próprio sistema? E agora? Por que isso acontece? Alguém continuou mantendo referências para objetos do projeto que não deveriam estar referenciados. Novamente o profiler vai ajudar.

Segundo sinal de leak: Cutucando mais um pouco percebemos que algumas Sessions do hibernate tambem não estavam sendo fechadas nem coletadas! Essa costuma ser uma forte indicação de vazamento de conexão. E no caso do Hibernate, isso poderia vir a gerar mais leak ainda, dado que muitas entidades ficariam presas no cache de primeiro nível, já que a sessão continuava aberta.

Objetos do hibernate apos o gc

Mas olhando a fundo, percebemos que a maior parte dessas sessões, exceto uma, estava injetada em objetos de modelo na sessao web. Isto é, são sessões usadas pelos nossos Repositories, que faz todo o sentido para o projeto e não é um memory leak, pois a sessão que era referenciada deveria estar fechada e com isso os objetos de cache de primeiro nível dele, coletados.

Sendo assim, partimos para testar funcionalidades que acreditavamos ter consumo grande de memória.

Primeiro sinal de consumo excessivo de memória: Encontramos uma funcionalidade que levantava cerca de 40 mil objetos na memória. Com isso, o consumo era de cerca de 40 megas de objetos só nesse select… mas o Tomcat estava configurado para 64 megas? O que acontecia? O consumo de memória aumentava, o garbage collector era invocado de sua maneira parcial, até que o consumo chegava ao topo, quando garbage collector full era rodado, pedindo mais memória para o sistema operacional.

Mas 64 ram não era espaço suficiente, então rodava o garbage collector full novamente, passando por todos os objetos da memória novamente, liberando mais um pouco e deixando um pouco mais de espaço, mas ainda não o suficiente. Cada vez mais, em intervalos de poucos segundos, o garbage collector era rodado e liberava menos espaço novo do que antes, tudo isso ainda na mesma requisição que usaria 40 megas… até que os espaços são tão pequenos que o processador fica a 100% de processamento, até acabar a memória e lançar o OutOfMemoryError. Nesse meio tempo, o servidor fica praticamente sem dar respostas, dado o alto uso de CPU.

Garbage collector rodando apos requisicao que criava diversos objetos

Garbage collector rodando apos requisicao que criava diversos objetos: note o garbage collector full rodado no final.

 Ok, encontramos um problema. Solução: filtrar esses 40 mil objetos para trazer menos objetos para a memória de uma vez só. No nosso caso uma simples busca por esses objetos foi o suficiente. O cliente não queria paginação e já havia recusado a paginação que havia sido feita no Sprint anterior.

Em outros casos, poderiamos usar resultados do hibernate que armazenam uma referencia somente para o objeto atual da lista, podendo garbage coletar os anteriores (uma StatelessSession, conforme discutido nos 7 hábitos dos desenvolvedores Hibernate altamente eficazes).

Esse ainda não era o grande problema, pois o nosso sintoma travava o servidordeixando o processador a 0%, e não a 100%.

Memory leak temporário encontrado: Voltando ao problema de leak anterior: o profiler mostrou que alguns objetos que estavam sobrando e não sendo garbage coletados. Com um pouco mais de procura, um heap dump mostra todas as referencias de um determinado objeto e, procurando quem referenciava aqueles que não iam para o garbage collector, encontramos que a implementação padrão do grupo Apache para a JSTL na tag c:forEach mantinha uma referencia para o último objeto iterado. Oops. Como assim?
 

c:forEach leak

c:forEach leak

A tag c:forEach, para seguir a especificação da JSTL, mantem uma referência para o último objeto iterado, mesmo após a iteração (as tags ficam em um pool do servidor de aplicação e são recicladas). Por isso, a referência era fixa e todo aquele pedaco da árvore de referÊncia dos objetos não poderia ser coletado até o proximo c:forEach usar aquela instância do pool novamente.

E agora o que isso pode causar?

Primeiro, as instâncias da tag só vão manter a referência por um tempo determinado. Quando utilizadas novamente, aquela árvore de objetos poderá ser coletada… o único problema aconteceria com um número muito grande de usuários executando uma query no servidor ao mesmo tempo. Isso não costuma acontecer em projetos de 1000 usuários, portanto não é uma preocupação no momento.

Novamente não resolvemos o problema principal, mas achamos mais um detalhe importante sobre uma biblioteca que utilizamos no dia a dia sem medo. Solução: não se preocupar pois o projeto não terá um número tão grande de usuários simultaneos para causar algum problema. Continuar usando a JSTL.

Por fim, as estatísticas do Hibernate Session Factory mostravam que raramente uma conexão se perdia. Após mais de 5000 conexões estabelecidas, três estavam abertas. Isto é, a conexão atual, e mais duas… As estatísticas do hibernate é uma das maneira mais simples de obter resultados sobre leaks de conexões, queries mal escritas ou possíveis pontos de bom uso do cache de segundo nível. Oolhando as estatísticas, confirmamos o session leak (connection leak):

c:forEach leak enquanto não apontar para outro objeto

session leak

Session leak é um dos erros mais comuns em projetos com o Hibernate. Infelizmente encontramos muitos projetos que acessam conexões em métodos estáticos, sem controle algum de quem invoca esse método e de quem libera essa sessão. Nesse projeto, o acesso a camada ORM era feita através de um Interceptador, como no Open Session in View, que é a maneira que mais gostamos de trabalhar, pois dificulta session leaks e facilita a criação de testes para seu código, já que será usado alguma maneira de inversão de controle.

Causa encontrada: Usando o Open Call Hieranchy do Eclipse, encontramos rapidamente 3 referências para abertura de sessões que não fecham ela de maneira adequada (com try/finally mal escritos)…

Solução: Abrir e fechar sessões corretamente!

Mas o que um connection leak pode causar no meu projeto? Tudo depende da configuração do seu connection pool. No caso do c3p0, o mais famoso e amplamente utilizado, existem algumas configurações que você pode fazer como, por exemplo, o número minimo de conexões no pool, c3p0.minPoolSize.

Porem, ao usar hibernate essa propriedade muda para hibernate.c3p0.min_size. Note que o hibernate
decidiu não seguir o padrão! Em uma conversa com o Diego Plentz, commiter do Hibernate e colaborador da Caelum, não encontramos rapidamente um motivo pelo qual o padrão não foi seguido. Talvez algum problema de conflito de propriedades configuradas em um mesmo arquivo, ou talvez para manter compatibilidade com o Hibernate 2.

O que acontecia nesse caso específico? A aplicação usava algumas configurações corretamente, como o minimo e máximo de conexões (nos testes de integração e de aceite, o máximo era 3). Mas uma outra configuração importantíssima estava escrita de maneira errada dentro de uma String do XML: configurar o tempo máximo que uma conexão que não está sendo usada seja eliminada, justamente para ignorar leaks. Algo como: se a conexão está idle, por, digamos, 1 minuto, considere que foi um leak, e traga ela de volta para o pool.

Causa encontrada: Como exatamente essa configuração estava sendo usada no valor errado, junto com o memory leak da implementação da JSTL, após a funcionalidade com session leak acontecer 3 vezes nos testes de integração, não existia mais nenhuma conexão disponível. O mesmo acontecia em produção com um número maior de vezes. Então as threads ficavam esperando uma conexao do connection pool.

Isso podia ser visto na visualização de threads do profiler: a cada nova requisição com o servidor sem responder, uma nova thread era criada pelo tomcat para atender a requisição, mas essa thread ficava em WAITING, isto é, ela estva esperando uma conexão ser liberada. Pela view de monitor era possível
verificar que ela aguardava algo do c3p0… a conexão… pronto! 

Threads aguardando monitores/sleeping etc

Threads aguardando monitores/sleeping etc

Encontramos o problema… as threads ficavam paradas (0% de processador) esperando por conexões que nunca chegariam (WAITING)! Um problema que veio por causa da configuração do c3p0 com o problema do connection leak. A solução é composta por duas tarefas: corrigir o session/connection leak e corrigir a configuração do c3p0. Encontramos facilmente o erro graças aos testes de integração.

Ufa! Prontos para o próximo desafio…

21 Comentários

  1. Leandro 02/09/2008 at 07:49 #

    Show de bola! Post fantástico!

    Não podia vir em uma hora melhor. Acabamos (eu e meu time) de ganhar uma missão de encontrarmos um problema de performance em uma aplicação core da empresa.

    Esse post já me deixou inspirado… mãos à obra… 🙂

  2. Tiago Albineli Motta 02/09/2008 at 07:58 #

    Muito boa a iniciativa de compartilhar essa experiência. Aqui onde trabalho tivemos um problema de performance causado por um mal uso da classe HashMap, detalhei melhor aqui http://programandosemcafeina.blogspot.com/2007/05/load-alto-causado-por-um-hashmap.htm . O problema acontecia pois estávamos assumindo que a classe HashMap era thread-safe, quando ela não é.

  3. Marcio 02/09/2008 at 14:04 #

    Post muito legal mesmo, com experiência muito rica.
    Uma pergunta, de curiosidade: quanto tempo foi usado na investigação desse problema?
    Abraços a todos.

  4. Adilson 02/09/2008 at 23:44 #

    Ótimo post,

    Temos exatamente este mesmo problema em nossa aplicação desenvolvida com VRaptor e Hibernate utilizando o banco de dados MySql.

    Seguimos todas as boas práticas e padrões de projetos e o problema persiste.

    Para solucionar o problema, você diz para corrigir o session/connection leak e corrigir a configuração do c3p0.

    Você poderia nos dizer como ficaria o arquivo de configuração c3p0?

    Abraços,

  5. Felipe Regalgo 03/09/2008 at 01:43 #

    Parabéns pelo Post!!!!!

    O JProfiler é pago… pq vcs não utilizam o profiler q vem com as novas versões da JVM (q é o jvisualvm.exe na pasta bin)??
    vcs usam algum outro profiler free?

    Falow

  6. Guilherme Silveira 03/09/2008 at 08:30 #

    Oi Adilson,

    Os sintomas podem ser os mesmos mas nem sempre a solucao é a mesma. O que vale é o caminho. O link do c3p0 tem a configuração adequada.

    O importante é voce passar pelos mesmos passos para, dado o seu sintoma, detectar o problema no seu caso. Na maior parte dos projetos session leak é um grande mal. A questão é como corrigir esse leak se o projeto não está bem estruturado.

    Felipe, usamos o JProfiler por gosto pessoal mesmo, que uso desde 2003 se não me engano, outros profilers podem retirar as mesmas informações.

    Abraco

  7. Guilherme Silveira 03/09/2008 at 08:34 #

    Marcio, so vi sua pergunta agora, desculpe.
    O processo de rodar o profiler e detectar os problemas demorou entre 1 e 2 dias completos com o melhor pessoal que nos temos para isso. Sendo que ja passamos por problemas parecidos em outros clientes. Depois foi analise de codigo, e antes foi analise da maquina.

    Abraco

  8. Rafael Rocha 03/09/2008 at 14:27 #

    Parabéns Guilherme pelo detalhes nas descrições. Gostaria de saber se você teve que habilitar/configurar algo no tomcat como o JMX para poder visualizar os dados obtidos a partir do JProfiler?

  9. Eduardo Simioni 04/09/2008 at 08:46 #

    Muito legal Guilherme, já passei por problemas parecidos com o c3p0.
    Outro ponto interessante é o número máximo de conexões. Em testes de stress realizados notamos uma diferença quase insignificante entre ter 100 conexões com o banco e 50.
    Entre deixar o DBA bravo e perder menos de 5% de performance (que já era boa) preferimos usar menos conexões.
    Claro que isto pode variar de acordo com a aplicação e só pode ser detectado com testes de stress…. ou em produção, como muita gente costuma testar 😉

    Abraço.

  10. Francisco Castro 04/09/2008 at 12:27 #

    Olá, gostei muito do seu blog e de sua abordagem.

    Parabéns!

    Um abraço

  11. Fabio Nascimento 05/09/2008 at 05:02 #

    Caramba.

    Putz, sempre que leio os posts de vocês, eu me lembro que tenho que estudar muito mais.

    Excelente aula.

    Fabio Nascimento

  12. Guilherme Silveira 07/09/2008 at 02:44 #

    Ola pessoal,

    Ficamos muito satisfeitos em saber que podemos ajudar. Rafael, sobre sua pergunta, o proprio JProfiler altera o script do tomcat para ativar o profiling da vm. Em outras palavras ele adiciona duas (ou tres?) opcoes a linha de comando que dizem que eh o agente de instrumentacao (pois fazemos atraves de instrumentacao de bytecode)

    Abraco

  13. Tiago Silveira 07/09/2008 at 05:18 #

    Mas a pergunta que não quer calar… vcs mandaram um fix pro JSTL? É claro que o ciclo de vida do elemento pendente tem que ser contido no ciclo de vida da renderização da página…

  14. Guilherme Silveira 07/09/2008 at 11:17 #

    Fala Tiago tudo bem?
    Nao enviamos nao pois o link que apontamos para o tracker do apache indica que nao eh um bug e sim eles estao seguindo o que a especificacao diz. Infelizmente eles preferem seguir a especificacao do que evitar um memory leak grosseiro. Mas como disse, em caso de aplicacoes medias, isso nao deve ser sentido por que as tags serao reutilizadas muito em breve. E em caso de aplicacoes grandes, o unico caso que quebraria a aplicacao que mudando isso nao quebraria seria se em determinado momento, as tags referenciassem arvores muito grandes e de repente ninguem mais usasse c:forEach… deixando um leak enorme e ninguem utilizando a tag novamente

  15. Luiz Aguiar 08/09/2008 at 01:23 #

    Muito bom Guilherme, excelente “estudo de caso”, imagino quantos projetos por ai podem ter problemas semelhantes e as pessoas nem sabem por onde começar caçar as bruxas.

  16. Thiago Faria 24/09/2008 at 01:34 #

    Parabéns pelo post.

    Já tive problemas com as tags do JSTL e Struts 1 (em 2005), e na época consegui solucionar criando uma classe que herdava cada tag problemática para limpar a sujeira deixada.

    Exemplo:

    public class SetTagWrapper extends SetTag
    implements TryCatchFinally {

    public void doFinally() {

    this.setTarget(null);
    this.setValue(null);

    }
    }

  17. Henrique S. 20/10/2008 at 10:41 #

    Rapaz… muito bom material!
    Legal este compartilhamento de experiência… rsrs
    Estou começando agora a participar em desenvolvimento de sistemas com muitos acessos e esta era minha maior preocupação: saber por onde começar quando um sistema travar.
    agora já tenho uma idéia: usar profiles, verificar CPU, rsrs parece elementar, mas p/ iniciante é uma ótima dica.
    Vocês costumam utilizar qual ferramenta para teste de carga? Estou começando com JMeter, tem outros?
    parabéns! 🙂

  18. Jefferson 16/07/2009 at 01:08 #

    Muito revelador este POST. Parabéns.

  19. Rafael 07/07/2017 at 09:29 #

    Vi tanta asneira na internet, de gente falando que o jdbc não libera memória no tomcat, etc. Até cheguei pensar em mudar algumas partes do código que tem jdbc e hibernet jpa. Na verdade a solução e tão simples, basta colocar no header ou footer System.gc(); (java) -> funciona realmente.. Não adianta colocar null para zerar objetos continua consumindo a memória do mesmo jeito.

  20. Paulo Silveira 26/07/2017 at 09:46 #

    cuidado, o System.gc é apenas uma indicacao pro GC rodar, pode ser que ele nao rode, pode ser que ele gaste tempo que nao precisava gastar. O pessoal nao considera uma boa pratica invoca-lo.

Deixe uma resposta