Categorias
Banco de dados Java Java EE Programação

Resolvendo “enq: TX – allocate ITL entry” com uma abordagem alternativa

Um dos problemas vistos num banco Oracle com muitos DML’s concorrentes é o evento de espera “enq: TX – allocate ITL entry”. O problema com esse evento é que as sessões fazendo os comandos de alteração nos registros demoram para executar, causando mais espera na aplicação.

Existem alguns jeitos de resolver esse evento de espera, entre eles:

  • Aumentar os parâmetros INITRANS e MAXTRANS da tabela / índice afetado
  • Mover a tabela para um tablespace com blocksize menor
  • Fazer um reorg da tabela
  • Reduzir a concorrência de DML’s na tabela

Sobre essas alternativas: Alterar o INITRANS e MAXTRANS das tabelas e índices é fácil, o problema é que os valores só são utilizados para os novos blocos criados. Além disso, valores maiores que 100 não diminuem essa contenção (conforme uma das referências).

Mover a tabela para um tablespace com blocksize menor pode ser feito de maneira online mas existem algumas condições nas quais o online não funciona. Além disso, em tabelas muito grandes e com alta taxa de DML’s, a aplicação acaba sentindo uma queda grande de performance nos DML’s durante essa movimentação.

Reduzir a concorrência dos DML’s parece ser uma solução boa, mas necessita a troca da lógica da aplicação, que nem sempre é viável / rápida de ser feita pois envolve a alteração para insert’s / update’s em batch.

Como funciona o ITL

O ITL (interested transaction list) é uma lista de transações que estão alterando os registros que estão localizados dentro de um bloco. Essa lista fica no cabeçalho do bloco e pode crescer conforme os parâmetros INITRANS, MAXTRANS e PCTFREE.

Sempre que uma transação quer alterar um registro em um bloco, ela deve se registrar no ITL. Se não existe um slot livre, o banco vai tentar criar um slot novo com base nos parâmetros informados acima. Caso o banco não possa criar mais slots, a transação vai esperar até um dos slots ser desocupado.

Aqui chegamos em um ponto interessante, as abordagens mencionadas acima para resolver esse problema envolvem:

  • Aumentar a quantidade de slots
  • Diminuir o número de transações concorrentes no mesmo bloco

Observando o que é o ITL, ele nada mais é do que uma fila. E existem dois jeitos de aumentar a vazão de uma fila:

  1. Aumentar o número de consumidores
  2. Diminuir o tempo de processamento de cada item da fila

O item 1 é coberto pelas abordagens mencionadas, mas em nenhum momento falamos sobre o item 2. A transação entra no ITL quando é enviado ao banco um DML e a transação só sai do ITL quando a mesma efetua o commit / rollback da transação. A abordagem que podemos seguir é diminuir o tempo entre o DML e o commit / rollback.

Uma pergunta que sempre surge é: por que a aplicação manda um DML e demora para efetuar o commit / rollback? Isto deve ser analisado à nível da aplicação, mas vamos citar aqui alguns exemplos do porquê isso acontece se você está utilizando o Hibernate / JPA.

Hibernate / JPA + Flush

Um dos erros que acontecem é criar ou alterar uma entidade e logo em seguida chamar o flush do JPA / Hibernate. Vamos ver o seguinte exemplo:

@Transactional
public void flush() {
	logger.info("Entering flush method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	entityManager.flush();
	logger.info("Entity Manager flushed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting flush method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:31:28.899 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.flush]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:31:28.900 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1979761636<open>)] for JPA transaction
2021-10-14 15:31:28.902 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@39fa396f]
2021-10-14 15:31:28.902  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Entering flush method
2021-10-14 15:31:28.902  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:31:28.902 DEBUG 10121 --- [nio-8081-exec-2] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:31:28.904  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:31:28.906 DEBUG 10121 --- [nio-8081-exec-2] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:31:28.908  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Entity Manager flushed
2021-10-14 15:31:28.908  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:31:28.908  INFO 10121 --- [nio-8081-exec-2] b.c.fnbrandao.artigo_itl.AppController   : Exiting flush method
2021-10-14 15:31:28.908 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:31:28.908 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1979761636<open>)]
2021-10-14 15:31:28.910 DEBUG 10121 --- [nio-8081-exec-2] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1979761636<open>)] after transaction

Ao chamar o método persist, o Hibernate mantém em memória que há um insert pendente, mas não envia o comando ao banco. Quando o método flush é executado, o Hibernate irá executar os DML’s pendentes de execução. No caso do exemplo, será enviado uma instrução de INSERT para o banco de dados, e essa transação irá ocupar um slot ITL. A transação só sairá do ITL após o método terminar, que é o momento em que o EJB / Spring irá verificar se deve mandar o commit ou rollback para o banco de dados para finalizar a transação.

A grande questão desse exemplo é o que acontece no método slowMethod. Se o método demorar para executar, o banco irá manter a transação por mais tempo no ITL já que a mesma ainda não enviou o commit ou rollback. O que vejo acontecer nos sistemas que estão em produção são chamadas remotas para outras aplicações, um processamento massivo de dados, etc.

A correção mais simples nesse caso seria remover o flush fazendo com o que o INSERT fosse enviado ao banco somente no momento que o EJB / Spring decide fazer o commit da transação:

@Transactional
public void withoutFlush() {
	logger.info("Entering withoutFlush method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	// Some slow processing
	slowMethod();
	logger.info("Exiting withoutFlush method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:31:45.521 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.withoutFlush]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:31:45.522 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(192140910<open>)] for JPA transaction
2021-10-14 15:31:45.524 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@4489334b]
2021-10-14 15:31:45.525  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entering withoutFlush method
2021-10-14 15:31:45.526  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:31:45.526 DEBUG 10121 --- [nio-8081-exec-3] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:31:45.528  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:31:45.528  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:31:45.528  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Exiting withoutFlush method
2021-10-14 15:31:45.528 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:31:45.528 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(192140910<open>)]
2021-10-14 15:31:45.528 DEBUG 10121 --- [nio-8081-exec-3] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:31:45.531 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(192140910<open>)] after transaction

Hibernate / JPA + Query Nativa

Um outro problema que acontece que é mais difícil de identificar é alterar a entidade e após isso rodar alguma query nativa. Vamos ver o seguinte exemplo:

@Transactional
public void nativeQuery() {
	logger.info("Entering nativeQuery method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	entityManager.createNativeQuery("select * from test2entity where id = 1").getResultList();
	logger.info("Native query executed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting nativeQuery method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:31:58.978 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.nativeQuery]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:31:58.979 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1469118830<open>)] for JPA transaction
2021-10-14 15:31:58.981 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@186a07d7]
2021-10-14 15:31:58.982  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Entering nativeQuery method
2021-10-14 15:31:58.982  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:31:58.982 DEBUG 10121 --- [nio-8081-exec-4] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:31:58.984  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:31:58.997 DEBUG 10121 --- [nio-8081-exec-4] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:31:59.012 DEBUG 10121 --- [nio-8081-exec-4] org.hibernate.SQL                        : select * from test2entity where id = 1
2021-10-14 15:31:59.016  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Native query executed
2021-10-14 15:31:59.016  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:31:59.016  INFO 10121 --- [nio-8081-exec-4] b.c.fnbrandao.artigo_itl.AppController   : Exiting nativeQuery method
2021-10-14 15:31:59.016 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:31:59.016 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1469118830<open>)]
2021-10-14 15:31:59.019 DEBUG 10121 --- [nio-8081-exec-4] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1469118830<open>)] after transaction

Seguindo o mesmo princípio do exemplo anterior, o insert só deveria ser enviado ao banco após a execução do método, mas ele será enviado no momento em que a query nativa será executada.

A correção nesse caso seria mapear a “query space” da query nativa, isso pode ser feito da seguinte maneira:

@Transactional
public void nativeQueryWithQuerySpace() {
	logger.info("Entering nativeQueryWithQuerySpace method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	NativeQuery<?> query = entityManager.createNativeQuery("select * from test2entity where id = 1").unwrap(NativeQuery.class);
	query.addSynchronizedEntityClass(Test2Entity.class);
	query.getResultList();
	logger.info("Native query executed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting nativeQueryWithQuerySpace method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:32:19.680 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.nativeQueryWithQuerySpace]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:32:19.681 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(696666563<open>)] for JPA transaction
2021-10-14 15:32:19.683 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@667cb8b8]
2021-10-14 15:32:19.683  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Entering nativeQueryWithQuerySpace method
2021-10-14 15:32:19.683  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:32:19.683 DEBUG 10121 --- [nio-8081-exec-5] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:32:19.685  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:32:19.686 DEBUG 10121 --- [nio-8081-exec-5] org.hibernate.SQL                        : select * from test2entity where id = 1
2021-10-14 15:32:19.687  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Native query executed
2021-10-14 15:32:19.687  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:32:19.687  INFO 10121 --- [nio-8081-exec-5] b.c.fnbrandao.artigo_itl.AppController   : Exiting nativeQueryWithQuerySpace method
2021-10-14 15:32:19.687 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:32:19.687 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(696666563<open>)]
2021-10-14 15:32:19.687 DEBUG 10121 --- [nio-8081-exec-5] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:32:19.691 DEBUG 10121 --- [nio-8081-exec-5] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(696666563<open>)] after transaction

O método addSynchronizedQuerySpace informa ao Hibernate qual é a entidade que está sendo consultada na query nativa e faz com que o insert só seja enviado ao banco quando o método termina de executar.

Observação: se a entidade informada no método addSynchronizedQuerySpace tiver alguma atualização pendente em memória no Hibernate, o mesmo irá efetuar os comandos DML’s antes de executar a query nativa. Esse caso pode ser visto no exemplo à seguir:

@Transactional
public void nativeQueryWithQuerySpaceFromSameEntity() {
	logger.info("Entering nativeQueryWithQuerySpaceFromSameEntity method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	NativeQuery<?> query = entityManager.createNativeQuery("select * from test1entity where id = 1").unwrap(NativeQuery.class);
	query.addSynchronizedEntityClass(Test1Entity.class);
	query.getResultList();
	logger.info("Native query executed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting nativeQueryWithQuerySpaceFromSameEntity method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:32:34.868 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.nativeQueryWithQuerySpaceFromSameEntity]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:32:34.869 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(158187605<open>)] for JPA transaction
2021-10-14 15:32:34.870 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@46972533]
2021-10-14 15:32:34.870  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Entering nativeQueryWithQuerySpaceFromSameEntity method
2021-10-14 15:32:34.870  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:32:34.871 DEBUG 10121 --- [nio-8081-exec-7] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:32:34.872  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:32:34.873 DEBUG 10121 --- [nio-8081-exec-7] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:32:34.874 DEBUG 10121 --- [nio-8081-exec-7] org.hibernate.SQL                        : select * from test1entity where id = 1
2021-10-14 15:32:34.876  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Native query executed
2021-10-14 15:32:34.876  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:32:34.876  INFO 10121 --- [nio-8081-exec-7] b.c.fnbrandao.artigo_itl.AppController   : Exiting nativeQueryWithQuerySpaceFromSameEntity method
2021-10-14 15:32:34.876 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:32:34.876 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(158187605<open>)]
2021-10-14 15:32:34.897 DEBUG 10121 --- [nio-8081-exec-7] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(158187605<open>)] after transaction

Hibernate / JPA + Query HQL / JPQL

O mesmo pode acontecer com uma query HQL / JPQL, desde que a query envolva as mesmas entidades que possuem alguma atualização pendente em memória no Hibernate. Diferente da query nativa onde é necessário chamar o método addSynchronizedQuerySpace para informar ao Hibernate quais as entidades estão envolvidas na query, numa query HQL / JPQL o Hibernate detecta automaticamente quais são essas entidades.

No exemplo a seguir, fazemos uma query que não tem relação com os objetos pendentes de atualização no Hibernate:

@Transactional
public void queryTest2() {
	logger.info("Entering queryTest1 method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	entityManager.createQuery("from Test2Entity where id = 1").getResultList();
	logger.info("Query executed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting queryTest2 method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:32:53.135 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.queryTest2]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:32:53.136 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(1333021676<open>)] for JPA transaction
2021-10-14 15:32:53.138 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@8eb649]
2021-10-14 15:32:53.138  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Entering queryTest1 method
2021-10-14 15:32:53.138  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:32:53.139 DEBUG 10121 --- [nio-8081-exec-8] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:32:53.140  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:32:53.199 DEBUG 10121 --- [nio-8081-exec-8] org.hibernate.SQL                        : select test2entit0_.id as id1_1_ from test2entity test2entit0_ where test2entit0_.id=1
2021-10-14 15:32:53.201  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Query executed
2021-10-14 15:32:53.202  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:32:53.202  INFO 10121 --- [nio-8081-exec-8] b.c.fnbrandao.artigo_itl.AppController   : Exiting queryTest2 method
2021-10-14 15:32:53.202 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:32:53.202 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(1333021676<open>)]
2021-10-14 15:32:53.202 DEBUG 10121 --- [nio-8081-exec-8] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:32:53.205 DEBUG 10121 --- [nio-8081-exec-8] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1333021676<open>)] after transaction

Já no próximo exemplo, fazemos uma query em uma entidade que tem relação com objetos pendentes de atualização no Hibernate, e o mesmo envia o insert ao banco antes da execução do select:

@Transactional
public void queryTest1() {
	logger.info("Entering queryTest1 method");
	Test1Entity e = new Test1Entity();
	logger.info("Entity created");
	entityManager.persist(e);
	logger.info("Entity persisted");
	entityManager.createQuery("from Test1Entity where id = 1").getResultList();
	logger.info("Query executed");
	// Some slow processing
	slowMethod();
	logger.info("Exiting queryTest1 method");
}

Ao executar o código, o seguinte log é gerado:

2021-10-14 15:35:18.406 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [br.com.fnbrandao.artigo_itl.AppController.queryTest1]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-14 15:35:18.408 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Opened new EntityManager [SessionImpl(396468559<open>)] for JPA transaction
2021-10-14 15:35:18.411 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@32bc28bc]
2021-10-14 15:35:18.411  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entering queryTest1 method
2021-10-14 15:35:18.411  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entity created
2021-10-14 15:35:18.411 DEBUG 10121 --- [nio-8081-exec-3] org.hibernate.SQL                        : select teste1_seq.nextval from dual
2021-10-14 15:35:18.413  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Entity persisted
2021-10-14 15:35:18.414 DEBUG 10121 --- [nio-8081-exec-3] org.hibernate.SQL                        : insert into test1entity (id) values (?)
2021-10-14 15:35:18.415 DEBUG 10121 --- [nio-8081-exec-3] org.hibernate.SQL                        : select test1entit0_.id as id1_0_ from test1entity test1entit0_ where test1entit0_.id=1
2021-10-14 15:35:18.416  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Query executed
2021-10-14 15:35:18.416  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Doing some slow stuff
2021-10-14 15:35:18.416  INFO 10121 --- [nio-8081-exec-3] b.c.fnbrandao.artigo_itl.AppController   : Exiting queryTest1 method
2021-10-14 15:35:18.416 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Initiating transaction commit
2021-10-14 15:35:18.416 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Committing JPA transaction on EntityManager [SessionImpl(396468559<open>)]
2021-10-14 15:35:18.418 DEBUG 10121 --- [nio-8081-exec-3] o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(396468559<open>)] after transaction

Exemplo real

Abaixo o gráfico do banco de dados com a contenção por causa do ITL. Esse evento fica agrupado no tipo Configuration:

Após as alterações da remoção de flush e correção para que as consultas não fizessem os comandos de insert / update irem muito cedo ao banco, o gráfico ficou dessa maneira:

Conclusões

Para analisar o evento de allocate ITL entry é primeiro necessário verificar se os parâmetros INITRANS, MAXTRANS e PCTFREE da tabela / índice estão configurados corretamente. 

Se após isso o banco ainda apresenta contenção, é necessário verificar o que a aplicação faz que causa essa contenção. Como mostrado anteriormente, um dos problemas são transações longas onde o DML é enviado muito antes do commit / rollback.

Se o Hibernate é utilizado, uma recomendação é evitar o uso de flush, verificar se as queries que estão sendo enviadas ao banco fazem com o que Hibernate mande os DML’s para o banco antes do ponto correto e mapear as entidades que têm relação com consultas nativas.

Outro problema que não foi abordado aqui foi a inserção / atualização de uma coluna indexada para múltiplos registros para um valor fixo.

Além disso, não foi abordado que uma outra solução para não ter tanta contenção nos índices nesse caso seria converter o mesmo para REVERSE, mas é necessário uma análise mais minuciosa pois o índice perde a habilidade de fazer range scan.

Os exemplos mostrado aqui estão em https://github.com/fabionb/artigo_itl

Referências

http://www.dba-oracle.com/t_enq_tx_alocate_itl_entry.htm

http://www.dba-oracle.com/t_insufficient_itl_slots.htm

http://www.proligence.com/itl_waits_demystified.html

http://www.dba-oracle.com/t_initrans.htm

https://oracle-base.com/articles/12c/online-move-table-12cr2

Deixe um comentário

O seu endereço de e-mail não será publicado. Campos obrigatórios são marcados com *

Esse site utiliza o Akismet para reduzir spam. Aprenda como seus dados de comentários são processados.