Categorias
Banco de dados Java Java EE Oracle Programação

High CPU causado pelo método copyRowsAsNeeded do driver do Oracle

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 = :id

A 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/1

O 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 = :id
SELECT t2 FROM Test2Entity t2
JOIN FETCH t2.test5Entities t5
WHERE t2.test1Entity.id = :id
SELECT t3 FROM Test3Entity t3
JOIN FETCH t3.test4Entities t4
WHERE t3.test1Entity.id = :id

Que 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 bags

Os exemplos mostrados aqui estão em https://github.com/fabionb/artigo_copyrowasneeded

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.