Um dos problemas que vejo acontecendo em diversos sistemas de produção é o pool de conexões com o banco de dados esgotar, através da exception abaixo:
java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 5000ms.
Geralmente, a primeira solução proposta é aumentar o pool de conexões. Só que após algum tempo o problema volta a ocorrer novamente. Olhando à partir do banco de dados não são vistas queries lentas e a maioria das conexões não estão executando nenhuma instrução, apenas estão ociosas, ou seja, abertas mas esperando a aplicação enviar algum comando.
Após algumas análises é possível por exemplo identificar que no mesmo momento uma dependência da aplicação com problema fica lenta.
Vamos simular isso com o código disponibilizado em https://github.com/fabionb/artigo_remotecall
A aplicação está configurada com 10 conexões no pool (padrão do Hikari) e 5 segundos de espera para obter a conexão do pool, após esse tempo a aplicação irá receber um erro caso não consiga obter a conexão.
Vamos primeiro executar o seguinte método:
@Transactional
public void testTransactionalOutside(int sleep, long start) {
logMaxId();
logger.info("In use connections {}", dataSource.getHikariPoolMXBean().getActiveConnections());
logger.info("Response {}",
restTemplate.getForObject(URI.create("http://localhost:8081/slowService/" + sleep), String.class));
RemoteCallLogEntity log = new RemoteCallLogEntity();
log.setSleep(sleep);
log.setTime(System.currentTimeMillis() - start);
entityManager.persist(log);
}
Para isso, basta chamar a url: http://localhost:8081/testTransactionalOutside/3000
Esse código executa um select no método logMaxId, depois exibe no log quantas conexões estão sendo utilizadas pela aplicação, faz uma chamada externa para um serviço que iremos simular a lentidão com base no parâmetro na url, e depois persiste um registro no banco de dados.
Executando essa url, vemos o seguinte log:
2021-10-18 11:17:16.697 INFO 10305 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : Max Log Id 2181
2021-10-18 11:17:16.697 INFO 10305 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : In use connections 1
2021-10-18 11:17:19.756 INFO 10305 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : Response null
Como podemos ver, 1 conexão está sendo utilizada no momento em que fazemos a chamada remota.
Vamos agora tentar realizar um simples teste de carga. Vamos simular a concorrência de 30 usuários realizando 300 requests nessa url. Primeiro, vamos simular que a dependência externa demora 50ms para dar a resposta:
ab -c 30 -n 300 http://localhost:8081/testTransactionalOutside/50
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Finished 300 requests
Server Software:
Server Hostname: localhost
Server Port: 8081
Document Path: /testTransactionalOutside/50
Document Length: 0 bytes
Concurrency Level: 30
Time taken for tests: 1.825 seconds
Complete requests: 300
Failed requests: 0
Total transferred: 27600 bytes
HTML transferred: 0 bytes
Requests per second: 164.39 [#/sec] (mean)
Time per request: 182.498 [ms] (mean)
Time per request: 6.083 [ms] (mean, across all concurrent requests)
Transfer rate: 14.77 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.6 0 4
Processing: 54 167 45.1 169 323
Waiting: 54 167 45.1 168 323
Total: 54 167 45.0 169 323
Percentage of the requests served within a certain time (ms)
50% 169
66% 173
75% 177
80% 178
90% 182
95% 278
98% 294
99% 315
100% 323 (longest request)
Como podemos ver, não tivemos erros e a o tempo médio por request foi 182 ms, enquanto o maior foi de 323 ms.
Agora vamos simular com o tempo de resposta do dependência externa em 3 segundos:
ab -c 30 -n 300 http://localhost:8081/testTransactionalOutside/3000
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Finished 300 requests
Server Software:
Server Hostname: localhost
Server Port: 8081
Document Path: /testTransactionalOutside/3000
Document Length: 0 bytes
Concurrency Level: 30
Time taken for tests: 64.683 seconds
Complete requests: 300
Failed requests: 99
(Connect: 0, Receive: 0, Length: 99, Exceptions: 0)
Non-2xx responses: 99
Total transferred: 41757 bytes
HTML transferred: 12870 bytes
Requests per second: 4.64 [#/sec] (mean)
Time per request: 6468.265 [ms] (mean)
Time per request: 215.609 [ms] (mean, across all concurrent requests)
Transfer rate: 0.63 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.3 0 2
Processing: 3011 5923 1049.8 6089 7955
Waiting: 3011 5923 1049.8 6089 7955
Total: 3011 5923 1049.7 6089 7955
Percentage of the requests served within a certain time (ms)
50% 6089
66% 6483
75% 6859
80% 6976
90% 7113
95% 7473
98% 7499
99% 7918
100% 7955 (longest request)
Com esse teste, tivemos 99 erros (pelos logs foram de falta de conexão no pool) e o tempo médio por request foi de 5923 ms, enquanto o maior foi de 7955 ms.
Durante o teste, se abrirmos o jconsole e verificarmos o pool do Hikari, vemos as seguintes informações:
As 10 conexões estão sendo utilizadas pela aplicação, enquanto 20 threads estão esperando que alguma dessas conexões fiquem livres para que elas possam seguir com o seu processamento.
Correção
A correção ideal nesse caso não é aumentar o pool de conexões, mas sim reduzir o tempo no qual a conexão fica associada com a thread para o mínimo possível. Qualquer recurso compartilhado (pool de conexões, cpu, memória, etc) deve ser utilizado da melhor maneira possível e pelo menor tempo possível para conseguir executar o processo.
O código que corrige esse problema está abaixo:
public void testTransactionalCorrect(int sleep, long start) {
logMaxId();
logger.info("In use connections {}", dataSource.getHikariPoolMXBean().getActiveConnections());
logger.info("Response {}",
restTemplate.getForObject(URI.create("http://localhost:8081/slowService/" + sleep), String.class));
remoteCallService.persistLog(sleep, System.currentTimeMillis() - start);
}
@Transactional
public void persistLog(int sleep, long time) {
RemoteCallLogEntity log = new RemoteCallLogEntity();
log.setSleep(sleep);
log.setTime(time);
entityManager.persist(log);
}
Removemos a anotação @Transactional do começo do método. Dessa maneira, quando o método logMaxId for executado, uma conexão será obtida do pool, a query será executada e a conexão voltará ao pool. Quando a chamada remota for feita, nenhuma conexão estará em uso pela thread atual, possibilitando que aquela conexão seja utilizada por outra thread. No momento em que vamos persistir o novo registro, marcamos o método com @Transactional, desse modo a conexão só será utilizada no momento em que deve: que é o momento em que a entidade deve ser persistida no banco.
Repetindo os testes, primeiramente com 50 ms:
ab -c 30 -n 300 http://localhost:8081/testTransactionalCorrect/50
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Finished 300 requests
Server Software:
Server Hostname: localhost
Server Port: 8081
Document Path: /testTransactionalCorrect/50
Document Length: 0 bytes
Concurrency Level: 30
Time taken for tests: 0.756 seconds
Complete requests: 300
Failed requests: 0
Total transferred: 27600 bytes
HTML transferred: 0 bytes
Requests per second: 396.80 [#/sec] (mean)
Time per request: 75.604 [ms] (mean)
Time per request: 2.520 [ms] (mean, across all concurrent requests)
Transfer rate: 35.65 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 1 2.5 0 13
Processing: 52 65 17.9 58 132
Waiting: 52 65 17.7 58 132
Total: 52 66 19.9 58 136
Percentage of the requests served within a certain time (ms)
50% 58
66% 63
75% 68
80% 70
90% 94
95% 124
98% 131
99% 131
100% 136 (longest request)
Como podemos ver, o tempo médio diminuiu para 66 ms e o maior request levou apenas 136 ms. Além disso, os percentis de tempo de resposta estão muito mais baixos que a implementação anterior.
Simulando agora com 3 segundos de tempo de resposta:
ab -c 30 -n 300 http://localhost:8081/testTransactionalCorrect/3000
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Finished 300 requests
Server Software:
Server Hostname: localhost
Server Port: 8081
Document Path: /testTransactionalCorrect/3000
Document Length: 0 bytes
Concurrency Level: 30
Time taken for tests: 33.634 seconds
Complete requests: 300
Failed requests: 0
Total transferred: 27600 bytes
HTML transferred: 0 bytes
Requests per second: 8.92 [#/sec] (mean)
Time per request: 3363.449 [ms] (mean)
Time per request: 112.115 [ms] (mean, across all concurrent requests)
Transfer rate: 0.80 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.7 0 4
Processing: 3003 3057 38.1 3060 3153
Waiting: 3003 3056 38.1 3060 3152
Total: 3003 3057 38.5 3060 3157
Percentage of the requests served within a certain time (ms)
50% 3060
66% 3071
75% 3076
80% 3082
90% 3116
95% 3141
98% 3148
99% 3153
100% 3157 (longest request)
Como podemos ver, o tempo médio por request cai para 3057 ms e os percentis ficam muito próximos a esse valor. Isso faz sentido já que o tempo de resposta deste serviço depende muito mais do tempo de resposta da dependência externa que foi configurado para 3 segundos do que qualquer outro tipo de processamento.:
Olhando o jconsole durante a execução do teste, a maior parte do tempo ele mostra as seguintes informações
Open Session In View
Um padrão altamente utilizado com aplicações Spring + Hibernate / JPA é o Open Session In View. Esse padrão faz com que a sessão do Hibernate (e consequentemente a conexão com o banco) fique associada ao request, inclusive durante a renderização das views. Esse padrão facilita o desenvolvimento porque ele evita o erro de LazyInitializationException, mas não é aconselhável já que isso pode causar diversos problemas de performance no banco de dados.
Vamos alterar o exemplo para religar o open session in view. Para isso, abra o arquivo application.properties e comente a propriedade spring.jpa.open-in-view.
Ao executar o request http://localhost:8081/testTransactionalCorrect/3000, o log exibe a seguinte informação:
2021-10-18 12:24:13.773 DEBUG 11277 --- [nio-8081-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2021-10-18 12:24:13.870 INFO 11277 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : Max Log Id 6184
2021-10-18 12:24:13.871 INFO 11277 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : In use connections 1
2021-10-18 12:24:13.925 DEBUG 11277 --- [nio-8081-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor
2021-10-18 12:24:16.948 DEBUG 11277 --- [nio-8081-exec-2] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
2021-10-18 12:24:16.956 INFO 11277 --- [nio-8081-exec-1] b.c.f.a.RemoteCallService : Response null
2021-10-18 12:24:16.958 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Found thread-bound EntityManager [SessionImpl(2008715250<open>)] for JPA transaction
2021-10-18 12:24:16.958 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Creating new transaction with name [br.com.fnbrandao.artigo_remotecall.RemoteCallService.persistLog]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-10-18 12:24:16.960 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Exposing JPA transaction as JDBC [org.springframework.orm.jpa.vendor.HibernateJpaDialect$HibernateConnectionHandle@2da68a2c]
2021-10-18 12:24:16.974 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Initiating transaction commit
2021-10-18 12:24:16.974 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Committing JPA transaction on EntityManager [SessionImpl(2008715250<open>)]
2021-10-18 12:24:16.986 DEBUG 11277 --- [nio-8081-exec-1] o.s.orm.jpa.JpaTransactionManager : Not closing pre-bound JPA EntityManager after transaction
2021-10-18 12:24:16.987 DEBUG 11277 --- [nio-8081-exec-1] o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor
Como podemos ver, ao fazer a chamada remota a aplicação associou aquela conexão com a thread.
Vamos agora rodar novamente o teste com 3 segundos de tempo de resposta:
ab -c 30 -n 300 http://localhost:8081/testTransactionalCorrect/3000
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Completed 300 requests
Finished 300 requests
Server Software:
Server Hostname: localhost
Server Port: 8081
Document Path: /testTransactionalCorrect/3000
Document Length: 0 bytes
Concurrency Level: 30
Time taken for tests: 64.315 seconds
Complete requests: 300
Failed requests: 100
(Connect: 0, Receive: 0, Length: 100, Exceptions: 0)
Non-2xx responses: 100
Total transferred: 41900 bytes
HTML transferred: 13000 bytes
Requests per second: 4.66 [#/sec] (mean)
Time per request: 6431.544 [ms] (mean)
Time per request: 214.385 [ms] (mean, across all concurrent requests)
Transfer rate: 0.64 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.7 0 4
Processing: 3012 5822 1114.7 6113 7627
Waiting: 3012 5822 1114.8 6112 7627
Total: 3013 5822 1114.5 6113 7627
Percentage of the requests served within a certain time (ms)
50% 6113
66% 6548
75% 6682
80% 6900
90% 7075
95% 7147
98% 7166
99% 7168
100% 7627 (longest request)
Como podemos ver, o tempo médio volta para os 5822 ms e os percentis pioram, sendo que o tempo máximo de request foi para 7627 ms.
Olhando o jconsole durante a execução do teste, novamente vemos a espera pelo pool retornar a conexão do banco:
Conclusões
Qualquer recurso compartilhado deve ser utilizado durante o menor tempo possível. Ao se fazer chamadas remotas, devemos garantir que esses recursos compartilhados (no exemplo acima a conexão com o banco de dados) não estão sendo utilizados enquanto esperamos a resposta do outro sistema (isso também vale para algum processamento local demorado, por exemplo).
Além disso, quando analisamos um problema, devemos saber diferenciar o que é causa e consequência. No caso demonstrado, a falta de conexões no pool pode ser vista num primeiro momento como a causa do problema, mas após analisar o banco de dados e ver que ele não tem queries lentas e as conexões estão ociosas, fica claro que esse sintoma é uma consequência. Após uma análise mais minuciosa vemos que a causa real é que a conexão está sendo “segurada” enquanto fazemos uma chamada remota à outro sistema, e este ficou lento por algum motivo.
Outro ponto importante é evitar trabalhar com o Open Session In View habilitado, pois ele pode causar o problema demonstrado aqui, além do que se depois da aplicação pronta quisermos desligar esse parâmetro, vamos ter que verificar todos os serviço para que não ocorra o erro de LazyInitializationException.
Referências