DB 커넥션 풀 누수 문제

dev-jjun·2023년 8월 17일

트러블 슈팅

목록 보기

4/8

ᑒ 오류

java.lang.Exception: **Apparent connection leak detected**
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:128) ~[HikariCP-4.0.3.jar:na]
	at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:122) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.internal.NonContextualJdbcConnectionAccess.obtainConnection(NonContextualJdbcConnectionAccess.java:38) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.acquireConnectionIfNeeded(LogicalConnectionManagedImpl.java:108) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getPhysicalConnection(LogicalConnectionManagedImpl.java:138) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.getConnectionForTransactionManagement(LogicalConnectionManagedImpl.java:276) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:284) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83) ~[hibernate-core-5.6.15.Final.jar:5.6.15.Final]
	at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:164) ~[spring-orm-5.3.29.jar:5.3.29]
	at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:421) ~[spring-orm-5.3.29.jar:5.3.29]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.startTransaction(AbstractPlatformTransactionManager.java:400) ~[spring-tx-5.3.29.jar:5.3.29]
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:373) ~[spring-tx-5.3.29.jar:5.3.29]
	at sopt.org.umbba.api.service.scheduler.ScheduleService.lambda$schedulePushAlarm$1(**ScheduleService.java:62**) ~[main/:na]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:95) ~[spring-context-5.3.29.jar:5.3.29]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]

✐ 문제 원인 및 해결 방안

데이터베이스와의 연결이 끊긴 누수 문제 → 과연 Dead Lock이 발생한 것일까?

해당 에러의 원인으로 의심되는 상황!

메모리 한계치를 초과하여 SELECT 쿼리를 보낸 경우 - https://cocococo331.tistory.com/29
하나의 쓰레드 내에서 같은 엔티티 매니저를 공유하는 경우

*하나의 EntityManager는 하나의 쓰레드에서만 사용가능하다! EntityManager 자체가 데이터베이스 연결과의 트랜잭션 상태를 유지하며 공유나 재사용이 불가능한 리소스이기 때문.

→ 쓰레드 풀 내에서 병렬로 이루어지는 작업들이 공유할 확률이 있나..?

답변은 NO!

위에서 엔티티 매니저를 주입받을 때 @PersistenceContext 어노테이션을 사용한다. 이는 각각의 쓰레드에 대해 별도의 엔티티 매니저가 생성됨을 보장한다.

또한 쓰레드에서 이루어지는 작업은 엔티티 매니저 내부에서 독립적으로 처리되기 떄문에 쓰레드 풀 내에서 병렬로 이루어지는 다른 작업들과 공유될 확률은 거의 없다고 보면 된다.

위에서 검출된 바로는 역시 스케줄링 작업 곳곳에서 누수가 발생하는 듯 보였고, EntityManager를 따로 주입받지 않는 부분에서도 같은 에러가 발생되어 명시적으로 예외가 발생되면 커넥션을 종료하도록 로직을 추가하였다.
```
import org.aspectj.lang.annotation.AfterThrowing;
import org.aspectj.lang.annotation.Aspect;
import org.springframework.stereotype.Component;

import java.sql.Connection;

@Aspect
@Component
public class ConnectionClosingAspect {

    @AfterThrowing(pointcut = "execution(* sopt.org.umbba.notification.service.*.*(..))", throwing = "ex")
    public void closeConnectionOnException(Exception ex) {
        Connection conn =  // DB 연결 정보로 connection 객체 가져오기
				
				if (conn != null && !conn.isClosed()) {
            conn.close();
        }
				
    }
}
```
하지만.. 일부 커넥션에만 누수가 발생한 것이라 새로운 Connection 객체를 만들었다가 종료시키는 건 크게 의미가 없었다고 한다..

스케줄링 작업 내에서 Thread.sleep(1000) 사용

쓰레드를 1초동안 잠시 멈추게 하는 sleep() 메서드를 호출하는 것은 불필요한 블로킹 작업일 수 있다. 잠시 멈추게 한다는 행위 자체가 쓰레드 풀의 리소스를 잠깐동안 차지하는 것이기 떄문에, 특히 여러 번 동시에 실행되는 이 스케줄링 작업에서는 꼭 필요하지 않다면 빼는 것을 권장한다.

sleep(1000)을 빼면?

java.util.concurrent.TimeoutException: null
	at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204) ~[na:na]
	at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.waitForRunningQueuesToStop(SimpleMessageListenerContainer.java:162) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.doStop(SimpleMessageListenerContainer.java:141) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.cloud.aws.messaging.listener.AbstractMessageListenerContainer.stop(AbstractMessageListenerContainer.java:352) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.stop(SimpleMessageListenerContainer.java:46) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.cloud.aws.messaging.listener.AbstractMessageListenerContainer.destroy(AbstractMessageListenerContainer.java:365) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.cloud.aws.messaging.listener.SimpleMessageListenerContainer.destroy(SimpleMessageListenerContainer.java:46) ~[spring-cloud-aws-messaging-2.2.6.RELEASE.jar:2.2.6.RELEASE]
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:213) ~[spring-beans-5.3.29.jar:5.3.29]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:587) ~[spring-beans-5.3.29.jar:5.3.29]
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:559) ~[spring-beans-5.3.29.jar:5.3.29]
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1163) ~[spring-beans-5.3.29.jar:5.3.29]
	at sopt.org.umbba.notification.config.GracefulShutdown.lambda$stopSqsListeners$0(GracefulShutdown.java:54) ~[main/:na]
	at java.base/java.util.LinkedHashMap$LinkedKeySet.forEach(LinkedHashMap.java:559) ~[na:na]
	at sopt.org.umbba.notification.config.GracefulShutdown.stopSqsListeners(GracefulShutdown.java:54) ~[main/:na]
	at sopt.org.umbba.notification.config.GracefulShutdown.stop(GracefulShutdown.java:48) ~[main/:na]
	at sopt.org.umbba.notification.config.GracefulShutdown.stop(GracefulShutdown.java:37) ~[main/:na]
	at org.springframework.context.support.DefaultLifecycleProcessor.doStop(DefaultLifecycleProcessor.java:235) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.context.support.DefaultLifecycleProcessor.access$300(DefaultLifecycleProcessor.java:54) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.context.support.DefaultLifecycleProcessor$LifecycleGroup.stop(DefaultLifecycleProcessor.java:374) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.context.support.DefaultLifecycleProcessor.stopBeans(DefaultLifecycleProcessor.java:207) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.context.support.DefaultLifecycleProcessor.onClose(DefaultLifecycleProcessor.java:130) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1070) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:174) ~[spring-boot-2.7.14.jar:2.7.14]
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1024) ~[spring-context-5.3.29.jar:5.3.29]
	at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:145) ~[spring-boot-2.7.14.jar:2.7.14]
	at java.base/java.lang.Iterable.forEach(Iterable.java:75) ~[na:na]
	at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:114) ~[spring-boot-2.7.14.jar:2.7.14]
	at java.base/java.lang.Thread.run(Thread.java:829) ~[na:na]

누수 검출 옵션 ON 으로 원인 추적하기
```
spring:
	datasource:
		hikari: leak-detection-threshold: 2000  *# default: 0(이용X)*
```
→ 로그에서 “ProxyLeakTask”를 찾아보면, 어디서 누수가 발생하는지 검출할 수 있다!

배포 서버 로그를 뒤져보니.. 매번 다른 데서 발생해서 일관되지 않다는 것을 알았다..!

다시 생각해보자

그렇다면, 검출 시간이 너무 짧아서 예민하게 반응하는 건 아닐까?

2000 → 60000으로 확 늘려줘보니까 바로 누수 관련 에러 및 경고는 뜨지 않았다..

*참고 - https://stackoverflow.com/questions/73688119/hikaripool-1-fill-pool-skipped-pool-is-at-sufficient-level

⇒ [결론] 처음에 hikariCP 관련 옵션 설정에서 누수 검출 시간을 초과할 때까지 연결이 되지 않으면 누수로 감지하고 WARN을 날리는 시간을 2000 (2초)로 설정해뒀는데, 이게 아무래도 너무 짧았던 모양이다. 또 이렇게 연결에 지연이 발생한 부분은 아무래도 트랜잭션 관리를 수동으로 해주는 부분이지 않을까 강한 의심이 든다. 계속 누수를 검출했다고 뜨는 부분도 트랜잭션 매니저를 가져오는 부분이었으니까!

TransactionDefinition transactionDefinition = new DefaultTransactionDefinition();
TransactionStatus transactionStatus = transactionManager.getTransaction(transactionDefinition);

dev-jjun

서버 개발자를 꿈꾸며 성장하는 쭌입니다 😽

이전 포스트

Thread.sleep()에서 발생한 InterruptedException

다음 포스트