Caçando seus gargalos com o Hibernate Statistics

Uma reclamação frequente dos novos usuários do Hibernate é o excesso de queries realizadas pelo framework, afetando não só a performance mas também a escalabilidade da aplicação. Será realmente culpa do framework? Práticas simples podem ajudar a enfrentar esses gargalos ao usar o Hibernate, mas como detectá-los numa aplicação que já foi mapeada sem muito cuidado? Uma das ferramentas mais úteis para o desenvolvedor na hora de otimizar e corrigir problemas com o Hibernate, além dos logs, são as estatísticas. Através do Hibernate Statistics poderemos dizer quantas vezes cada entidade, coleção (relacionamento) e query está sendo carregada/executada, quantas vezes o cache foi usado, tempo médio de cada query, etc. Em mão desses dados, temos mais pistas de onde colocar cache, configurar batchsize e fazer joins com fetch eager.

Para habilitar o uso das estatísticas do Hibernate temos duas formas. A primeira através do arquivo de configuração do hibernate e a segunda programaticamente. Ao escolher a maneira programática temos a vantagem de poder habilitar e desabilitar a coleta de estatísticas a qualquer momento. Mas não se preocupe, pois podemos usar as duas ao mesmo tempo!

Para habilitar através do arquivo de configuração basta adicionar a seguinte propriedade no hibernate.cfg.xml:

<property name="hibernate.generate_statistics">true</property>

Programaticamente usamos o SessionFactory:

sessionFactory.getStatistics().setStatisticsEnabled(true);

Passada etapa de configuração vamos ver um exemplo de ajuda que o hibernate statistics pode dar. Para o exemplo abaixo temos uma classe utilitária para facilitar a criação de Sessions e das Statistics:

public class HibernateUtil {

	private static SessionFactory factory;

	static {
		factory = new Configuration().configure().buildSessionFactory();
	}

	public static Session openSession() {
		return factory.openSession();
	}

	public static Statistics getStatistics() {
		if (!factory.getStatistics().isStatisticsEnabled()) {
			factory.getStatistics().setStatisticsEnabled(true);
		}
		return factory.getStatistics();
	}
}

O indicado nesses casos seria usar algum container de Injeção de Dependências para fazer este controle, mas esse é um outro assunto.

O caso abaixo é o exemplo Pessoa que possui uma lista de Telefone. Nesse código estamos simulando a criação de 10 pessoas e seus respectivos telefones. Porém se notarmos bem o código, estamos salvando primeiro o telefone e depois a pessoa. Essa ordem acabará gerando (dependendo do dialeto hibernate utilizado no banco) um update para cada par de Pessoa e Telefone que inserirmos, pois o hibernate ao salvar o telefone ainda não tem o id da pessoa para enviar no insert de telefone.

Com o Hibernate Statistics podemos conferir quantos updates foram disparados através do método getEntityUpdateCount e conferir se realmente estamos disparando as operações da maneira correta:

public class TesteQuantidadeUpdatesOrdemErrada {
	public static void main(String[] args) {
		Session session = HibernateUtil.openSession();
		Statistics statistics = HibernateUtil.getStatistics();
		long antes = statistics.getEntityUpdateCount();
		
		for (int i = 0; i < 10; i++) {
			Transaction transaction = session.beginTransaction();
			
			Pessoa p = new Pessoa();
			p.setNome("Caelum "+1);
			Telefone t1 = new Telefone();
			t1.setValor("5571-2751");
			t1.setTipo("comercial");
			t1.setPessoa(p);
			
			session.save(t1);
			session.save(p);
			transaction.commit();
		}
		long depois = statistics.getEntityUpdateCount();
		System.out.println(depois-antes);
	}
}

Ao rodar o código temos a saída “Updates disparados:10”. Graças ao Hibernate Statistics foi fácil de ver esses updates a mais, sem ter de ficar verificando os enormes logs de queries que uma aplicação pode gerar. Para resolver essa pendência basta inverter a ordem dos saves que teremos 0 updates no hibernate statistics.

O código abaixo insere dez pessoas no banco:

public static void main(String[] args) {
		Statistics statistics = HibernateUtil.getStatistics();

		long abertas = statistics.getSessionOpenCount();
		long fechadas = statistics.getSessionCloseCount();
		System.out.println("Sessoes nao fechadas:"+(abertas-fechadas));
		
		for (int i = 0; i < 10; i++) {
			Session session = HibernateUtil.openSession();
			Transaction transaction = session.beginTransaction();
			try{
				Pessoa p = new Pessoa();
				p.setNome("Caelum "+1);
				session.save(p);
				transaction.commit();
				session.close();
			}catch (Exception e) {
				System.err.println(e);
				transaction.rollback();
			}
		}
		abertas = statistics.getSessionOpenCount();
		fechadas = statistics.getSessionCloseCount();
		System.out.println("Sessoes nao fechadas:"+(abertas-fechadas));
	}
}

Em uma execução normal teríamos todas as sessões fechadas sem problema algum, porém vamos simular um erro a cada 3 saves:

Pessoa p = new Pessoa();
p.setNome("Caelum " + 1);
if (i%3 == 0) {
	throw new RuntimeException();
}
session.save(p);
transaction.commit();
session.close();

Agora vemos através do hibernate statistics que nosso try/catch está falho e que, caso algo saia errado, esquecemos de fechar a sessão no catch. O certo neste caso era fechar a sessão no bloco finally, evitando que por causa de esquecimento alguém não tenha fechado a sessão.

}catch (Exception e) {
	System.err.println(e);
	transaction.rollback();
}finally{
	session.close();
}

Agora o hibernate statistics mostrará que todas as sessões foram fechadas para esse caso. Vale lembrar que ainda devemos verificar se o close terminou com sucesso, eliminando as possibilidades de uma sessão ou transação permanecer aberta (em último caso, deve ser logado com prioridade).

Podemos até coletar informações sobre as transações, adicionando as linhas de código abaixo, mostrando a quantidade de transações totais e as que deram certo:

System.out.println("Quantidade total de Transacoes:" +
    statistics.getTransactionCount());
System.out.println("Quantidade de Transacoes ok:" +
    statistics.getSuccessfulTransactionCount());

É de grande ajuda que os sistemas tenham uma página que possa mostrar algumas dessas informaçãoes a qualquer hora. Inclusive o hibernate tem um método que mostra no log um resumo de todas as estatísticas importantes, para ver esse imprimi-lo basta invocar logSummary da classe Statistics.

O Hibernate Statistics está cheio de métodos uteis, uma pequena lista dos principais:

  • getEntity[Delete,Insert,Load,Update]Count():long
    serve para obter informações sobre os CRUD das entidades
  • getQueryExecutionMaxTimeQueryString():String
    retorna a consulta mais demorada
  • getQueryExecutionMaxTime():long
    retorna o tempo de execução da consulta mais demorada
  • getSecondLevelCacheHitCount():long
    retorna quantas vezes o hibernate conseguiu a informação que queria
    através do cache
  • getSecondLevelCacheMissCount():long
    retorna quantas vezes o hibernate teve que ir no banco buscar a
    informação que queria pois ela não estava no cache

Existem muitos outros métodos interessantes que podem ser conferidos no javadoc da classe Statistics. Suas informações vai te ajudar a decidir que queries devem ser reescritas, colocadas no second level cache, quais relacionamentos devem ser carregados em modo batch, etc.

Apenas as estatísticas do Hibernate não vão ajudar a resolver todos os problemas da aplicação, porém facilitará muito quando você tiver que achar pequenas falhas, inconsistências, lentidão e excessos na comunicação aplicação-banco. Monitorar muito bem sua aplicação é essencial, para não depender apenas de utilizar profilings e debuggers, que deveriam ser ferramentas apenas nos casos mais graves.

15 Comentários

  1. Raphael 08/06/2011 at 21:38 #

    Finalmente moreira! hehe!

    mto bom!

  2. Paulo Silveira 08/06/2011 at 23:53 #

    Pois é. Devemos focar sempre em monitoração e logging, para deixar profiling e debug só nos casos complicados, como último recurso. Já descobri muito cache que só dava miss, seja por tamanho pequeno, politica ruim ou mesmo porque aquela entidade não se enquadrava bem.

  3. Edilmar Alves 09/06/2011 at 16:19 #

    Este link também é interessante sobre o assunto… http://www.javalobby.org/java/forums/t19807.html

  4. Renato 13/06/2011 at 07:55 #

    Muito interessanteo artigo.

    Alguém sabe se é possível obter essas estatísticas enquanto usando o hibernate em conjunto com EJB3.1? Digo isso porque nesse caso eu não tenho a factory a minha disposição.

  5. Thiago 13/06/2011 at 10:16 #

    Opa, muito boa a explicação sobre o Hibernate Statistics, no projeto que trabalho, pegamos muito forte nesta parte (logging e monitoração), agora uma pergunta sobre o Hibernate Statistics, ele causa algum impacto de performance na aplicação ? ou a implementação dele não causa nem impacto ?

    att.

  6. Paulo Silveira 13/06/2011 at 11:47 #

    @Renato é possivel sim com EJB, basta configurar através do XML. Mas para pegar os dados, terá de acessar a SessionFactory mesmo. Para isso, pegue um EntityManager, invoque o getDelegate que devolve um Session. Ai, atraves da Session, invoque getSessionFactory, que te devolvera a SessionFactory que é usada na delegacao do EMF.

    @Thiago causa impacto sim. É algo mínimo, mas causa.

  7. Guilherme Moreira 13/06/2011 at 13:16 #

    @Thiago Como o Paulo disse esse impacto é mínimo, porém você pode habilitar programaticamente as estatísticas somente quando surgir a necessidade e desabilitar (também programaticamente) quando você achar o que estava procurando.

  8. Fabio Kenji 13/06/2011 at 16:56 #

    Se nao me engano, o proprio hibernate disponibiliza uma interface JMX onde eh possível acessar essas estatísticas. Se voce rodar a sua aplicação no JBoss, por exemplo, eh possível declarar o bean JMX no deploy da sua aplicação e acessa-lo via jmx-console do container.

    http://community.jboss.org/wiki/PublishingStatisticsThroughJMX

    No entanto, quando deployamos este bean, a maior dificuldade que tivemos foi interpretar as estatísticas geradas e identificar possíveis pontos de melhoria.

  9. Paulo Silveira 13/06/2011 at 17:21 #

    @Fabio, bem observado.

    Mais importante e difícil que ter as estatísticas, é saber tirar valor delas. Às vezes tiramos conclusões bem erradas. Creio que caiba um outro post para explicar algumas situações onde colocar um cache, batch size ou trocar um fetch profile pode ser pior.

  10. Lucas Pereira Caixeta 14/06/2011 at 15:40 #

    O Moreira até colocou uma foto xique pra fazer o artigo hehehehehe

    Parabéns, ótimo artigo!

  11. Altieres de Matos 01/07/2011 at 11:47 #

    Ótimo post, já tinha ouvido falar desse Statistics, mais ainda não tive tempo de estudá-lo e pratica-lo. Agora já sei ao menos como começar!

    Abraços.

  12. Natan 08/11/2011 at 11:51 #

    Parabens, ótimo, post me ajudou muito!

  13. Gilmar M. dos Santos 12/03/2012 at 10:40 #

    Parabéns enriqueci ainda mais meus conhecimentos.

  14. Flávio 18/04/2012 at 10:16 #

    Valeu Guilherme. Muito bom.

  15. Thiago 20/07/2012 at 15:58 #

    Valeu Guilherme, já to usando aqui!! abs!

Deixe uma resposta