Categorias
Banco de dados Java Java EE Programação

Chamadas remotas em contexto transacional de banco de dados

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

https://www.baeldung.com/spring-open-session-in-view

https://thorben-janssen.com/lazyinitializationexception/

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.