DBCP Dead Lock Thread Dump로 확인.

taehee kim·2023년 5월 16일

Thread Dump

DBCP deadlock

목록 보기

2/2

1. 글 작성 배경

시리즈 이전 포스트에서
1. GenerationType.AUTO
2. Mysql
3. Thread pool size > DBCP size
조건에서 발생하는 DBCP데드락을 분석하고 해결하였다.

2. 문제 상황

2-1. DBCP Deadlock 직관적인 원인 분석의 한계

DBCP 데드락임을 알아챈 근거는 다음과 같다.

JMeter로 데이터를 세팅하기 위해 큰 부하를 주지 않았음에도 아무 요청도 처리 되지 않는다.
DBCP는 모두 점유되어있다. Db Connection 요청 대기열지속해서 쌓인고 Application에는 Connection Timeout 예외가 발생한다.
가장 중요한점은, DBCP가 할당되고 있음에도 RDS의 사용률은 매우 적다.

이전 테스트에서 같은 정도의 부하를 줄 경우 RDS의 CPU사용률이 증가하였기 때문에 RDS자체에 요청이 되지 않는것이라고 판단하였다. 해당 내용으로 검색한 결과 비슷한 사례를 찾을 수 있었고 해결을 하였다.

이 방식은 경험적으로 추론하는 것에는 도움이 되지만 원인을 정확하게 확정짓기는 어려움 부분이 있다.

3. Thread dump를 통한 요청 스레드의 상태 확인

참고 자료: https://d2.naver.com/helloworld/10963

connection 객체의 점유 상황을 알 방법을 찾던 도중 Thread의 상태를 볼 수 있는 Thread Dump를 통해 Connection 객체 점유 상황을 알 수 있음을 아게 되었다. Connection 객체를 요구하면서 대기하는 스레드는 TIMED-WAITING이 된다.

3-1. Thread 상태

Thread dump를 이해하기 위해서는 Thread 상태를 알아야한다. 여기서 Thread는 JVM내에서 생성된 User Thread이다.

NEW

스레드가 생성되었지만 아직 실행되지 않은 상태

RUNNABLE

현재 CPU를 점유하고 작업을 수행 중인 상태. 운영체제의 자원 분배로 인해 WAITING 상태가 될 수도 있다.

BLOCKED

Monitor를 획득하기 위해 다른 스레드가 락을 해제하기를 기다리는 상태

WAITING

wait() 메서드, join() 메서드, park() 메서드 등를 이용해 대기하고 있는 상태

TIMED_WAITING

sleep() 메서드, wait() 메서드, join() 메서드, park() 메서드 등을 이용해 대기하고 있는 상태.
WAITING 상태와의 차이점은 메서드의 인수로 최대 대기 시간을 명시할 수 있어 외부적인 변화뿐만 아니라 시간에 의해서도 WAITING 상태가 해제될 수 있다는 것이다.

3-2. Thread에서 데드락이 발생했다면 TIMED_WAITING상태

DBCP Deadlock 이 발생한것이라면 Thread dump를 통해 tomcat의 스레드 상태를 확인했을 때 DBCP의 connection을 받지 못해 TIMED_WAITING(Connection_timeout이 있기 때문에 한정 대기이다)일 것이다.

jps command

실행되고 있는 jvm목록을 보여주는 커맨드.

jps
takim@gimtaehuiui-MacBookPro jps
97185 Kafka
97186 Kafka
6340 Launcher
6341 ModuleApiApplication
99094 ApacheJMeter.jar
93707 RemoteMavenServer36
923
7101
97183 QuorumPeerMain
10718 Jps

Thread dump

jstack command 활용
6341은 application의 jvm pid

jstack 6341 > thread.dump

cat thread.dump | grep -A1 'http-nio-8080-exec'

takim@gimtaehuiui-MacBookPro  ~  
"http-nio-8080-exec-1" #52 daemon prio=5 os_prio=31 cpu=843.66ms elapsed=1354.84s tid=0x0000000123c3e800 nid=0xab03 waiting on condition  [0x0000000172bc3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-4" #55 daemon prio=5 os_prio=31 cpu=450.56ms elapsed=1354.84s tid=0x0000000124242800 nid=0xb203 waiting on condition  [0x00000001731e5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-6" #57 daemon prio=5 os_prio=31 cpu=481.67ms elapsed=1354.84s tid=0x0000000122ce6800 nid=0x14e03 waiting on condition  [0x00000001735ff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-8" #59 daemon prio=5 os_prio=31 cpu=458.64ms elapsed=1354.84s tid=0x0000000123d8f800 nid=0x14b03 waiting on condition  [0x0000000173a15000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-9" #60 daemon prio=5 os_prio=31 cpu=533.80ms elapsed=1354.85s tid=0x0000000123d85800 nid=0x14803 waiting on condition  [0x0000000173c21000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-10" #61 daemon prio=5 os_prio=31 cpu=426.33ms elapsed=1354.85s tid=0x0000000123d8a800 nid=0x14603 waiting on condition  [0x0000000173e2d000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-11" #108 daemon prio=5 os_prio=31 cpu=438.81ms elapsed=1271.65s tid=0x0000000122d72800 nid=0xe313 waiting on condition  [0x000000016fcad000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-15" #112 daemon prio=5 os_prio=31 cpu=437.93ms elapsed=1271.64s tid=0x000000012426f800 nid=0x10c13 waiting on condition  [0x00000001783c5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-18" #132 daemon prio=5 os_prio=31 cpu=115.18ms elapsed=536.26s tid=0x0000000123dd0000 nid=0xad07 waiting on condition  [0x0000000173809000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-20" #134 daemon prio=5 os_prio=31 cpu=116.98ms elapsed=536.25s tid=0x0000000124330800 nid=0xb307 waiting on condition  [0x00000001781bb000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-21" #146 daemon prio=5 os_prio=31 cpu=51.28ms elapsed=95.40s tid=0x0000000123d3b800 nid=0xb00f waiting on condition  [0x0000000172dcf000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-22" #147 daemon prio=5 os_prio=31 cpu=60.71ms elapsed=95.40s tid=0x0000000123ce0000 nid=0xe213 waiting on condition  [0x0000000172fd9000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-23" #148 daemon prio=5 os_prio=31 cpu=58.81ms elapsed=95.39s tid=0x0000000123d03000 nid=0xb613 waiting on condition  [0x00000001733f3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-24" #149 daemon prio=5 os_prio=31 cpu=58.45ms elapsed=95.39s tid=0x0000000123cdd000 nid=0xb40b waiting on condition  [0x0000000177da1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
--
"http-nio-8080-exec-25" #150 daemon prio=5 os_prio=31 cpu=54.84ms elapsed=95.39s tid=0x0000000121cd8800 nid=0xa01f waiting on condition  [0x0000000177fad000]
   java.lang.Thread.State: TIMED_WAITING (parking)

4. 결과

모든 요청 스레드 들이 DBCP connection을 얻기 위해 한정 대기를 하고 있는 상황임을 확인할 수 있다.

taehee kim

Fail Fast

이전 포스트