22.06.04)
해당 글은 Dead Lock이 아닌 단순 커넥션 누수의 문제입니다.
※ Hikari, Connections pool, dead lock에 대한 설명이 포함되어 있지 않습니다
결론부터 말하자면
저의 경우엔 개발자의 실수였습니다.
체감상 2주 동안 걸쳐서 발견됐던 에러인데 막상 찾고보니 허무하기도 하고, 이와 동시에 커넥션 풀을 공부할 수 있어서 좋은(?) 기회였다고 생각합니다.
해결 방법은 가장 아래에 있습니다.
어떤 친구였나
spring-compose | 2021-08-05 13:05:52.412 WARN 7 --- [io-8080-exec-10] o.h.engine.jdbc.spi.SqlExceptionHelper : SQL Error: 0, SQLState: null
spring-compose | 2021-08-05 13:05:52.413 ERROR 7 --- [io-8080-exec-10] o.h.engine.jdbc.spi.SqlExceptionHelper : HikariPool-1 - Connection is not available, request timed out after 30000ms.
spring-compose | 2021-08-05 13:05:52.416 ERROR 7 --- [io-8080-exec-10] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.dao.DataAccessResourceFailureException: Unable to acquire JDBC Connection; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection] with root cause
spring-compose |
spring-compose | java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30000ms.
spring-compose | at com.zaxxer.hikari.pool.HikariPool.createTimeoutException(HikariPool.java:695) ~[HikariCP-3.4.5.jar!/:na]
spring-compose | at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:197) ~[HikariCP-3.4.5.jar!/:na]
사진에서의 에러 보고는 첫 날이 8월 5일이지만, 저 Dead lock 에러때문에 에러 채널을 따로 생성하고 에러 체크를 하기 시작했습니다.
해결까지 약 1주일 정도 소요되었네요.
처음엔 별 대수롭지 않게 생각했습니다.
간헐적으로 발생(그럴 수 밖에 없었던 이유가 있었죠..)하기도 했고, DEBUG 모드로 뒤져봐도 명확한 원인을 찾을 수 없었습니다.
그 이후 docker restart로 연명하기 시작했죠..
왜 못찾았나?
나중에 알게 되었지만, 간헐적으로 발생했던 이유는 특정 상황(시나리오)에서만 발생하기 때문입니다.
최근에 와서야, 계속해서 Dead lock이 발생하는 로그를 보고 뭔가 잘못되었다는 것을 직감했습니다.
PR 체크는 안했나?
프로젝트 마감일이 점점 다가오고 프론트에서 급하게 필요한 기능들이 있어서,
팀원을 믿고 PR Merge를 바로바로 했던 시기가 있었습니다.
즉, 안전한 작동, 꼼꼼한 점검보다는 빠른 구현에 초점을 맞추기 시작했습니다.(반성 또 반성중입니다)
에러 해결을 위한 과정
우리가 Dead lock이 발생할만한 상황인가?
같은 스레드 간에 EntityManager를 사용하지도 않았고, 그렇다고 한 번에 엄청난 사용자가 몰릴 일도 없고(심지어 50명이 들어와 테스트 할 때는 멀쩡) 대체 무엇인가...
hikari 설정의 문제인가...
그래서 hikrari 설정도 건들여보았습니다.
#application.yml
datasource:
hikari:
idle-timeout: 10000
max-lifetime: 420000
connection-timeout: 10000
validation-timeout: 10000
알아서 만료되고 자원 반환 하겠지!!!
그럴리가요.
생각보다 고집이 강했습니다. 한번 가져간 자원은 결코 돌려주지 않더라구요.
대체 왜? 커넥션 상황을 지켜보자
도저히 머리로 이 Dead lock이 생기는 상황이 이해가 안됐습니다.
일단 로그를 더 살펴보자 생각하고 불나는 구글링을 통해 hikari stats를 추적하기 시작했습니다.
#application.yml
logging:
level:
com.zaxxer.hikari.HikariConfig: DEBUG
com.zaxxer.hikari: TRACE
그리고 로그인-로그아웃을 반복했더니 글쎄,,
HikariPool-1 - Pool stats (total=30, active=1, idle=29, waiting=0)
HikariPool-1 - Pool stats (total=30, active=2, idle=28, waiting=0)
HikariPool-1 - Pool stats (total=30, active=3, idle=27, waiting=0)
HikariPool-1 - Pool stats (total=30, active=4, idle=26, waiting=0)
결국 30회 로그인 동안 idle상태의 커넥션이 0이 되면서 dead lock 에러를 출력했던 것입니다...
로그인 할 때마다 (팀 생성 가능 여부를 조회할 때 마다) 자원을 하나씩 꿀꺽해버린거죠 ㅠㅠ
아, 이걸 누수라고 하는구나?
여기까지 1주일 정도 걸렸습니다.
마침내 누수를 탐지할 수 있는 기능을 찾게되었습니다.
datasource:
hikari:
leak-detection-threshold: 2000
누수를 검출해주는 옵션인데 default는 0입니다 (검출하지 않겠다는 뜻)
저는 최소값인 2000ms로 설정을 해두고 로그인을 시도합니다.
2021-08-13 00:50:29.425 WARN 7 --- [l-1 housekeeper] com.zaxxer.hikari.pool.ProxyLeakTask : Connection leak detection triggered for com.mysql.cj.jdbc.ConnectionImpl@7123f3b7 on thread https-jsse-nio-8080-exec-2, stack trace follows
java.lang.Exception: Apparent connection leak detected
오 드디어 찾았어!
와 leak-detection을 왜 몰랐을까요...
커넥션 누수가 발생하는 곳을 단번에 짚어줍니다... 그 위치또한 너무나 정확해서 보자마자 원인을 알아챘습니다..
하하 허무하죠. 네 원인은 사용한 EntityManager를 close 해주지 않았기 때문입니다.
당연히 되어 있을 것이라 생각했던 부분인데, 보고나서 곧장 em.close()와 예외 처리를 해주고 이후에 et.rollback까지 처리하였습니다.
반성 또 반성
이건 개인의 잘못이 아닌 팀 모두의 잘못입니다 ㅠㅠ
초기에 발견하지 못했던 것은 커넥션 30이 다 사용될 때까지 아무런 일이 없었기 때문입니다.
dead lock이 발생하고 나서야 어 뭐야 어디가 문제야? 하고 찾지만,,
이미 그 사이에 수 많은 로그가 찍히면서 정작 봐야할 곳은 놓쳐버리게 되더라구요.
이번 삽질을 통해 또 많은걸 배웠습니다.
그리고 너무 당연한 말이지만, PR이 올라오면 "급하면 그냥 머지하세요!"가 아니라 꼼꼼하게 살펴볼 것.
사용한 자원은 꼭 제자리에 둘 것.
커넥션 누수엔 leak-detection.
참고한 사이트