Algum tempo atrás me deparei com uma situação onde uma aplicação começava a utilizar muita CPU, o load da máquina física subia demais e o tempo de resposta da aplicação acabava piorando junto com o uso de cpu / load da máquina.
Para identificar o que estava causando, colocamos um script na máquina física que sempre que o load passava um determinado valor ele começava a tirar thread dumps da aplicação.
Os threads dumps possuíam diversas threads paradas no mesmo ponto:
"http-nio-8081-exec-6" #42 daemon prio=5 os_prio=0 cpu=8869.88ms elapsed=34.97s tid=0x00007f6f58009560 nid=0x9ad runnable [0x00007f6f6cbf6000]
java.lang.Thread.State: RUNNABLE
at oracle.jdbc.driver.T4CTTIrxd.copyRowsAsNeededByOffset(T4CTTIrxd.java:1405)
at oracle.jdbc.driver.T4CTTIrxd.copyRowsAsNeeded(T4CTTIrxd.java:1313)
at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1502)
at oracle.jdbc.driver.T4CTTIrxd.unmarshal(T4CTTIrxd.java:1289)
at oracle.jdbc.driver.T4C8Oall.readRXD(T4C8Oall.java:850)
at oracle.jdbc.driver.T4CTTIfun.receive(T4CTTIfun.java:543)
at oracle.jdbc.driver.T4CTTIfun.doRPC(T4CTTIfun.java:252)
at oracle.jdbc.driver.T4C8Oall.doOALL(T4C8Oall.java:612)
at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:226)
at oracle.jdbc.driver.T4CPreparedStatement.fetch(T4CPreparedStatement.java:1023)
at oracle.jdbc.driver.OracleStatement.fetchMoreRows(OracleStatement.java:3353)
at oracle.jdbc.driver.InsensitiveScrollableResultSet.fetchMoreRows(InsensitiveScrollableResultSet.java:736)
at oracle.jdbc.driver.InsensitiveScrollableResultSet.absoluteInternal(InsensitiveScrollableResultSet.java:692)
at oracle.jdbc.driver.InsensitiveScrollableResultSet.next(InsensitiveScrollableResultSet.java:406)
- locked <0x00000000950a4408> (a oracle.jdbc.driver.T4CConnection)
at com.zaxxer.hikari.pool.HikariProxyResultSet.next(HikariProxyResultSet.java)
at org.hibernate.loader.Loader.getRowsFromResultSet(Loader.java:1035)
at org.hibernate.loader.Loader.processResultSet(Loader.java:990)
at org.hibernate.loader.Loader.doQuery(Loader.java:959)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:349)
at org.hibernate.loader.Loader.doList(Loader.java:2843)
at org.hibernate.loader.Loader.doList(Loader.java:2825)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2657)
at org.hibernate.loader.Loader.list(Loader.java:2652)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:506)
at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:400)
at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:219)
at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1414)
at org.hibernate.query.internal.AbstractProducedQuery.doList(AbstractProducedQuery.java:1636)
at org.hibernate.query.internal.AbstractProducedQuery.list(AbstractProducedQuery.java:1604)
at org.hibernate.query.internal.AbstractProducedQuery.getSingleResult(AbstractProducedQuery.java:1652)
at br.com.fnbrandao.artigo_copyrowasneeded.AppController.test(AppController.java:88)Olhando o código fonte do driver, o método copyRowsAsNeeded era executado para cada linha / coluna retornada pela query. Investigando a query JPQL enviada para o banco:
SELECT t1 FROM Test1Entity t1
JOIN FETCH t1.test2Entities t2
JOIN FETCH t2.test5Entities t5
JOIN FETCH t1.test3Entities t3
JOIN FETCH t3.test4Entities t4
WHERE t1.id = :idA query buscava 1 registro específico no banco, mas acabava fazendo diversos fetch’s (para evitar a LazyInitializationException). O problema é que esses fetch’s eram feitos em relacionamentos One to Many. A query final enviada para o banco era:
SELECT
test1entit0_.id AS id1_0_0_,
test2entit1_.id AS id1_1_1_,
test5entit2_.id AS id1_4_2_,
test3entit3_.id AS id1_2_3_,
test4entit4_.id AS id1_3_4_,
-- 150 columns here!
test4entit4_.test3entity_id AS test12_3_3__,
test4entit4_.id AS id1_3_3__
FROM
test1entity test1entit0_
INNER JOIN test2entity test2entit1_ ON test1entit0_.id = test2entit1_.test1entity_id
INNER JOIN test5entity test5entit2_ ON test2entit1_.id = test5entit2_.test2entity_id
INNER JOIN test3entity test3entit3_ ON test1entit0_.id = test3entit3_.test1entity_id
INNER JOIN test4entity test4entit4_ ON test3entit3_.id = test4entit4_.test3entity_id
WHERE
test1entit0_.id = 1;O Hibernate retornava apenas 1 entidade principal para a aplicação (test1entity), com 25 entidades do tipo test2entity e test3entity. A test4entity e test5entity retornavam 625 cada! O problema é que no banco de dados é feito um produto cartesiano para trazer todos os dados em apenas uma query, o que faz com que a consulta retornasse 390.625 linhas! Além disso, a consulta retorna as informações com 157 colunas por linha, o que faz com que o método copyRowsAsNeeded do driver do Oracle tenha que processar 61.328.125 de valores, o que causava o uso intenso de CPU da aplicação (sendo que boa parte dos dados estão duplicados nas linhas).
Para demonstrar, utilizei o comando ab do apache tools para realizar um teste simples. O teste irá simular 10 clientes simultâneos fazendo 20 requests:
ab -c 10 -n 20 http://localhost:8081/test/1O resultado do teste:
Concurrency Level: 10
Time taken for tests: 71.831 seconds
Complete requests: 20
Failed requests: 0
Total transferred: 7452300 bytes
HTML transferred: 7450200 bytes
Requests per second: 0.28 [#/sec] (mean)
Time per request: 35915.529 [ms] (mean)
Time per request: 3591.553 [ms] (mean, across all concurrent requests)
Transfer rate: 101.32 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 0
Processing: 10826 28990 5017.5 29732 34424
Waiting: 10801 28981 5018.1 29725 34394
Total: 10826 28990 5017.6 29733 34424
Percentage of the requests served within a certain time (ms)
50% 29733
66% 31926
75% 32648
80% 32653
90% 33489
95% 34424
98% 34424
99% 34424
100% 34424 (longest request)O gráfico de CPU da aplicação:
Para corrigir o problema, podemos quebrar a query em 3 queries JPQL separadas:
SELECT t1 FROM Test1Entity t1
WHERE t1.id = :idSELECT t2 FROM Test2Entity t2
JOIN FETCH t2.test5Entities t5
WHERE t2.test1Entity.id = :idSELECT t3 FROM Test3Entity t3
JOIN FETCH t3.test4Entities t4
WHERE t3.test1Entity.id = :idQue serão convertidas para as sequintes queries no banco de dados:
SELECT
test1entit0_.id AS id1_0_,
test1entit0_.column1 AS column2_0_,
-- 98 columns here!
test1entit0_.column99 AS column101_0_
FROM
test1entity test1entit0_
WHERE
test1entit0_.id = 1;SELECT
test2entit0_.id AS id1_1_0_,
-- 24 columns here!
test5entit1_.id AS id1_4_0__
FROM
test2entity test2entit0_
INNER JOIN test5entity test5entit1_ ON test2entit0_.id = test5entit1_.test2entity_id
WHERE
test2entit0_.test1entity_id = 1;SELECT
test3entit0_.id AS id1_2_0_,
-- 24 columns here!
test4entit1_.id AS id1_3_0__
FROM
test3entity test3entit0_
INNER JOIN test4entity test4entit1_ ON test3entit0_.id = test4entit1_.test3entity_id
WHERE
test3entit0_.test1entity_id = 1;A diferença aqui está na quantidade de informação retornada. A primeira query retorna 101 colunas em apenas 1 linha, enquanto a segunda e terceira queries retornam 26 colunas em 625 linhas cada. Fazendo as contas, o método copyRowsAsNeeded terá que processar 32.601 valores ao invés de 61.328.125 valores quando apenas uma query era executada no banco. Isso implica em uma redução de 99,9% no processamento!
Além disso, a query única demorava aproximadamente 10 segundos para executar, enquanto a quebra em 3 queries demoravam respectivamente 3ms, 75ms e 75ms, totalizando 153ms. A redução de tempo de processamento no banco de dados foi de 98%!
Rodando novamente o teste com a correção implementada:
E o resultado do ab:
Concurrency Level: 10
Time taken for tests: 0.534 seconds
Complete requests: 20
Failed requests: 0
Total transferred: 7452300 bytes
HTML transferred: 7450200 bytes
Requests per second: 37.44 [#/sec] (mean)
Time per request: 267.087 [ms] (mean)
Time per request: 26.709 [ms] (mean, across all concurrent requests)
Transfer rate: 13624.07 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.4 0 1
Processing: 71 191 83.9 205 343
Waiting: 65 186 85.7 203 339
Total: 71 191 84.0 206 343
Percentage of the requests served within a certain time (ms)
50% 206
66% 223
75% 261
80% 275
90% 342
95% 343
98% 343
99% 343
100% 343 (longest request)Como pode ser visto, o tempo de execução do teste caiu de 71 segundos para apenas 534 milissegundos, uma redução de 99%!
Conclusões
É preciso tomar cuidado no uso do Hibernate, o ideal é sempre verificar as queries que ele envia ao banco e verificar o plano de execução e a quantidade de informações retornadas. Além disso, é necessário também verificar se a aplicação realmente necessita de todas as informações retornadas. O Hibernate facilita demais a obtenção de informações do banco, mas ao mesmo tempo faz com que você deixe passar despercebido alguns detalhes que podem piorar a escalabilidade e disponibilidade da aplicação.
Outro ponto é que dependendo de como é implementado o mapeamento, alguns problemas (como esse do exemplo) são camuflados. Se os relacionamentos One to Many fossem mapeados com uma lista ao invés de um set, o Hibernate não iria permitir o fetch de múltiplas relacionamentos pois iria ser lançada a seguinte exception:
org.hibernate.loader.MultipleBagFetchException: cannot simultaneously fetch multiple bagsOs exemplos mostrados aqui estão em https://github.com/fabionb/artigo_copyrowasneeded
