Cloudera CDH/CDP 및 Hadoop EcoSystem, Semantic IoT등의 개발/운영 기술을 정리합니다. gooper@gooper.com로 문의 주세요.
*출처 : http://d2.naver.com/helloworld/10963
장애가 발생했을 때나 기대보다 웹 애플리케이션이 느리게 동작할 때, 우리는 스레드 덤프를 분석해 봐야 합니다. 이 글에서는 스레드 덤프를 획득하는 방법부터 어떻게 스레드 덤프를 해석해야 하는지, 어떤 점을 눈여겨 봐야 하는지 설명하겠습니다. 스레드 덤프가 불친절한 암호같이 느껴진 분들께 이 글이 도움이 되기를 바랍니다.
Java 그리고 스레드
웹 서버에서는 많은 수의 동시 사용자를 처리하기 위해 수십~수백 개 정도의 스레드를 사용한다. 두 개 이상의 스레드가 같은 자원을 이용할 때는 필연적으로 스레드 간에 경합(Contention)이 발생하고 경우에 따라서는 데드락(Deadlock)이 발생할 수도 있다.
경합이란 어떤 스레드가 다른 스레드가 획득하고 있는 락(lock)이 해제되기를 기다리는 상태를 말한다. 웹 애플리케이션에서 여러 스레드가 공유 자원에 접근하는 일은 매우 빈번하다. 대표적으로 로그를 기록하는 것도 로그를 기록하려는 스레드가 락을 획득하고 공유 자원에 접근하는 것이다.
데드락은 스레드 경합의 특별한 경우인데, 두 개 이상의 스레드에서 작업을 완료하기 위해서 상대의 작업이 끝나야 하는 상황을 말한다.
스레드 경합 때문에 다양한 문제가 발생할 수 있으며, 이런 문제를 분석하기 위해서는 스레드 덤프(Thread Dump)를 이용한다. 각 스레드의 상태를 정확히 알 수 있기 때문이다.
Java 스레드 배경 지식
스레드 동기화
스레드는 다른 스레드와 동시에 실행할 수 있다. 여러 스레드가 공유 자원을 사용할 때 정합성을 보장하려면 스레드 동기화로 한 번에 하나의 스레드만 공유 자원에 접근할 수 있게 해야 한다. Java에서는 Monitor를 이용해 스레드를 동기화한다. 모든 Java 객체는 하나의 Monitor를 가지고 있다. 그리고 Monitor는 하나의 스레드만 소유할 수 있다. 어떠한 스레드가 소유한 Monitor를 다른 스레드가 획득하려면 해당 Monitor를 소유하고 있는 스레드가 Monitor를 해제할 때까지 Wait Queue에서 대기하고 있어야 한다.
스레드 상태
스레드 덤프를 분석하려면 스레드의 상태를 알아야 한다. 스레드의 상태는 java.lang.Thread 클래스 내부에 State라는 이름을 가진 Enumerated Types(열거형)으로 선언되어 있다.
그림 1 스레드 상태
- NEW: 스레드가 생성되었지만 아직 실행되지 않은 상태
- RUNNABLE: 현재 CPU를 점유하고 작업을 수행 중인 상태. 운영체제의 자원 분배로 인해 WAITING 상태가 될 수도 있다.
- BLOCKED: Monitor를 획득하기 위해 다른 스레드가 락을 해제하기를 기다리는 상태
- WAITING: wait() 메서드, join() 메서드, park() 메서드 등를 이용해 대기하고 있는 상태
- TIMED_WAITING: sleep() 메서드, wait() 메서드, join() 메서드, park() 메서드 등을 이용해 대기하고 있는 상태. WAITING 상태와의 차이점은 메서드의 인수로 최대 대기 시간을 명시할 수 있어 외부적인 변화뿐만 아니라 시간에 의해서도 WAITING 상태가 해제될 수 있다는 것이다.
스레드의 종류
Java 스레드는 데몬 스레드(Daemon Thread)와 비데몬 스레드(Non-daemon Thread)로 나눌 수 있다.
데몬 스레드는 다른 비데몬 스레드가 없다면 동작을 중지한다. 사용자가 직접 스레드를 생성하지 않더라도, Java 애플리케이션이 기본적으로 여러 개의 스레드를 생성한다. 대부분이 데몬 스레드인데 가비지 컬렉션이나, JMX 등의 작업을 처리하기 위한 것이다. 'static void main(String[] args)' 메서드가 실행되는 스레드는 비데몬 스레드로 생성되고, 이 스레드가 동작을 중지하면 다른 데몬 스레드도 같이 동작을 중지하게 되는 것이다. 이 main 메서드가 실행되는 스레드를 HotSpot VM에서는 VM Thread라고 부른다.
스레드 덤프 획득
스레드 덤프를 획득하는 방범은 여러 가지가 있지만, 이 글에서는 가장 많이 사용하는 스레드 덤프 획득 방법 세 가지를 소개하겠다. 스레드 덤프는 획득할 당시의 스레드 상태만 알 수 있기 때문에 스레드 상태 변화를 확인하려면 5초 정도의 간격으로 5~10회 정도 획득하는 것이 좋다.
jstack을 이용하는 방법
JDK 1.6 이상을 사용하고 있다면 Microsoft Windows에서도 jstack을 이용해 스레드 덤프를 획득할 수 있다. jstack으로 스레드 덤프를 획득하려면, 먼저 수행 중인 Java 애플리케이션 프로세스의 PID를 확인해야 한다. PID는 다음과 같이 jps로 확인한다.
[user@linux ~]$ jps -v
18812 Jps -Denv.class.path=/home1/user/java/apps/threaddump.jar --Dapplication.home=/home1/user/java/jdk1.6.0_24 -Xms8m 25780 RemoteTestRunner -Dfile.인코딩=UTF-8 25590 sun.rmi.registry.RegistryImpl 2999 -Dapplication.home=/home1/user/java/jdk1.6.0_24 -Xms8m 26300 sun.tools.jps.Jps -mlvV -Dapplication.home=/home1/user/java/jdk1.6.0_24 -Xms8m |
jps로 추출한 PID를 인수로 넣어 jstack을 실행하면 스레드 덤프를 획득한다.
[user@linux ~]$ jstack 18812 |
Java VisualVM을 이용하는 방법
Java VisualVM과 같은 GUI 프로그램으로도 스레드 덤프를 획득할 수 있다.
그림 2 Visual VM을 이용한 스레드 덤프
왼쪽 패널은 실행 중인 프로세스의 목록이다. 이 목록에서 정보를 원하는 프로세스를 클릭한 다음 오른쪽 패널에서 Threads 탭을 선택하면 스레드의 정보를 실시간으로 확인할 수 있다. 스레드 덤프를 파일로 저장하려면 스레드 정보가 나타나는 화면 오른쪽 위의 Thread Dump 버튼을 클릭한다.
kill을 이용하는 방법
Linux 환경에서는 kill 명령어로 스레드 덤프를 획득할 수 있다. kill 명령어의 인수로 사용할 PID는 ps -ef | grep java 명령어로 확인한다.
[user@linux ~]$ ps -ef | grep java
user 25780 1 0 11:23 pts/3 00:00:00 /home1/user/java/jdk1.6.0_24/bin/java -Djava.util.logging.config.file=/home1/user/java/apps/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Dfile.encoding=UTF-8 -XX:PermSize=256m -XX:MaxPermSize=256m -Xms1024m -Xmx1024m -server -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home1/user/java/apps/tomcat/logs -XX:+UseParNewGC -XX:+CMSParallelRemarkEnabled -XX:+UseConcMarkSweepGC -Djava.endorsed.dirs=/home1/user/java/apps/tomcat/common/endorsed -classpath :/home1/user/java/apps/tomcat/bin/bootstrap.jar:/home1/user/java/apps/tomcat/bin/commons-logging-api.jar -Dcatalina.base=/home1/user/java/apps/tomcat -Dcatalina.home=/home1/user/java/apps/tomcat -Djava.io.tmpdir=/home1/user/java/apps/tomcat/temp org.apache.catalina.startup.Bootstrap start
user 26335 25361 0 15:49 pts/3 00:00:00 grep java |
ps 명령어로 확인한 PID를 다음과 같이 kill 명령어의 인수인 -3(또는 -QUIT나 -SIGQUIT)과 함께 사용하여 스레드 덤프를 획득한다.
[user@linux ~]$ kill -3 25780 |
스레드 덤프의 정보
획득한 스레드 덤프에는 다음과 같은 정보가 들어 있다.
"pool-1-thread-13" prio=6 tid=0x000000000729a000 nid=0x2fb4 runnable [0x0000000007f0f000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) - locked <0x0000000780b7e688> (a java.io.InputStreamReader) at java.io.InputStreamReader.read(InputStreamReader.java:167) at java.io.BufferedReader.fill(BufferedReader.java:136) at java.io.BufferedReader.readLine(BufferedReader.java:299) - locked <0x0000000780b7e688> (a java.io.InputStreamReader) at java.io.BufferedReader.readLine(BufferedReader.java:362) |
- 스레드 이름: 스레드의 고유 이름. java.lang.Thread 클래스를 이용해 스레드를 생성하면 Thread-(Number) 형식으로 스레드 이름이 생성된다. java.util.concurrent.ThreadFactory 클래스를 이용했으면 pool-(number)-thread-(number) 형식으로 스레드 이름이 생성된다.
- 우선순위: 스레드의 우선순위
- 스레드 ID: 스레드의 ID. 해당 정보를 이용해 스레드의 CPU 사용, 메모리 사용 등 유용한 정보를 얻을 수 있다.
- 스레드 상태: 스레드의 상태.
- 스레드 콜스택: 스레드의 콜스택(Call Stack) 정보.
스레드 덤프 유형별 패턴
락을 획득하지 못하는 경우(BLOCKED)
한 스레드가 락을 소유하고 있어 다른 스레드가 락을 획득하지 못해 애플리케이션의 전체적인 성능이 느려지는 경우이다.
다음 스레드 덤프 예에서는 BLOCKED_TEST pool-1-thread-1 스레드가 <0x0000000780a000b0> 락을 소유한 상태에서 동작하고 있어, BLOCKED_TEST pool-1-thread-2 스레드와 BLOCKED_TEST pool-1-thread-3 스레드는 <0x0000000780a000b0> 락을 획득하기 위해 대기하고 있는 상태이다.
"BLOCKED_TEST pool-1-thread-1" prio=6 tid=0x0000000006904800 nid=0x28f4 runnable [0x000000000785f000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:282) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123) - locked <0x0000000780a31778> (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:432) - locked <0x0000000780a04118> (a java.io.PrintStream) at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:202) at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:272) at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:85) - locked <0x0000000780a040c0> (a java.io.OutputStreamWriter) at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:168) at java.io.PrintStream.newLine(PrintStream.java:496) - locked <0x0000000780a04118> (a java.io.PrintStream) at java.io.PrintStream.println(PrintStream.java:687) - locked <0x0000000780a04118> (a java.io.PrintStream) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:44) - locked <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState$1.run(ThreadBlockedState.java:17) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
Locked ownable synchronizers: - <0x0000000780a31758> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
"BLOCKED_TEST pool-1-thread-2" prio=6 tid=0x0000000007673800 nid=0x260c waiting for monitor entry [0x0000000008abf000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:43) - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState$2.run(ThreadBlockedState.java:26) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
Locked ownable synchronizers: - <0x0000000780b0c6a0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
"BLOCKED_TEST pool-1-thread-3" prio=6 tid=0x00000000074f5800 nid=0x1994 waiting for monitor entry [0x0000000008bbf000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadBlockedState.monitorLock(ThreadBlockedState.java:42) - waiting to lock <0x0000000780a000b0> (a com.nbp.theplatform.threaddump.ThreadBlockedState) at com.nbp.theplatform.threaddump.ThreadBlockedState$3.run(ThreadBlockedState.java:34) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662)
Locked ownable synchronizers: - <0x0000000780b0e1b8> (a java.util.concurrent.locks.ReentrantLock$NonfairSync) |
데드락 상태인 경우
스레드 A가 작업을 계속하려면 스레드 B가 소유한 락을 획득해야 하고, 스레드 B가 작업을 계속하려면 스레드 A가 소유한 락을 획득해야 해서 데드락 상태에 있는 경우이다.
다음 스레드 덤프 예에서 DEADLOCK_TEST-1 스레드는 <0x00000007d58f5e48> 락을 소유하고 있으며, DEADLOCK_TEST-2 스레드가 소유한 <0x00000007d58f5e60> 락을 획득하려 한다. 한편 DEADLOCK_TEST-2 스레드는 <0x00000007d58f5e60> 락을 소유하고 있으며, DEADLOCK_TEST-3 스레드가 소유한 <0x00000007d58f5e78> 락을 획득하려 한다. 그리고 DEADLOCK_TEST-3 스레드는 <0x00000007d58f5e78> 락을 수유하고 있으며, DEADLOCK_TEST-1 스레드가 소유한 <0x00000007d58f5e48> 락을 획득하려 한다.
이렇게 서로 상대가 소유하고 있는 락을 획득하기 위해 대기하기 때문에 한 스레드가 자신의 락을 해제하기 전까지는 데드락 상태가 해제되지 않게 된다.
"DEADLOCK_TEST-1" daemon prio=6 tid=0x000000000690f800 nid=0x1820 waiting for monitor entry [0x000000000805f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)
Locked ownable synchronizers: - None
"DEADLOCK_TEST-2" daemon prio=6 tid=0x0000000006858800 nid=0x17b8 waiting for monitor entry [0x000000000815f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e60> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)
Locked ownable synchronizers: - None
"DEADLOCK_TEST-3" daemon prio=6 tid=0x0000000006859000 nid=0x25dc waiting for monitor entry [0x000000000825f000] java.lang.Thread.State: BLOCKED (on object monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.goMonitorDeadlock(ThreadDeadLockState.java:197) - waiting to lock <0x00000007d58f5e48> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.monitorOurLock(ThreadDeadLockState.java:182) - locked <0x00000007d58f5e78> (a com.nbp.theplatform.threaddump.ThreadDeadLockState$Monitor) at com.nbp.theplatform.threaddump.ThreadDeadLockState$DeadlockThread.run(ThreadDeadLockState.java:135)
Locked ownable synchronizers: - None |
원격 서버로부터 메시지 수신을 받기 위해 계속 대기하는 경우
다음 스레드 덤프 예에서는 스레드가 계속 RUNNABLE 상태에 있어 문제가 될 만한 부분이 없는 것처럼 보인다. 하지만 스레드 덤프를 시간순으로 나열하면, socketReadThread 스레드가 계속 소켓을 읽으려 무한정으로 대기하고 있는 상태이다.
"socketReadThread" prio=6 tid=0x0000000006a0d800 nid=0x1b40 runnable [0x00000000089ef000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:264) at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:306) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:158) - locked <0x00000007d78a2230> (a java.io.InputStreamReader) at sun.nio.cs.StreamDecoder.read0(StreamDecoder.java:107) - locked <0x00000007d78a2230> (a java.io.InputStreamReader) at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:93) at java.io.InputStreamReader.read(InputStreamReader.java:151) at com.nbp.theplatform.threaddump.ThreadSocketReadState$1.run(ThreadSocketReadState.java:27) at java.lang.Thread.run(Thread.java:662) |
WAIT 상태에 있는 경우
스레드가 계속 WAIT 상태를 유지하고 있는 경우이다.
다음 스레드 덤프 예에서 IoWaitThread 스레드는 LinkedBlockingQueue 객체에서 메시지를 획득하기 위해 계속 대기하고 있다. 만약 계속 LinkedBlockingQueue에 메시지가 들어오지 않는 다면 해당 스레드의 상태가 바뀌지 않게 된다.
"IoWaitThread" prio=6 tid=0x0000000007334800 nid=0x2b3c waiting on condition [0x000000000893f000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000007d5c45850> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:156) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1987) at java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:440) at java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:629) at com.nbp.theplatform.threaddump.ThreadIoWaitState$IoWaitHandler2.run(ThreadIoWaitState.java:89) at java.lang.Thread.run(Thread.java:662) |
스레드 리소스를 정상적으로 정리하지 못하는 경우
불필요한 스레드가 계속해서 늘어나는 경우이다. 스레드 리소스를 정상적으로 정리 못하고 있는 경우이기 각 스레드를 정리하는 모습 혹은 스레드가 종료되는 조건을 확인하는 것이 좋다.
스레드 덤프를 이용한 문제 해결 예제
상황1: CPU 사용률이 비정상적으로 높을 때
애플리케이션을 수행할 때 CPU 사용률이 비정상적으로 높다면 스레드 덤프를 이용하여 문제를 파악할 수 있다.
먼저 다음과 같이 CPU를 가장 많이 점유하는 스레드가 무엇인지 추출한다.
추출한 결과에서 CPU를 가장 많이 사용하는 LWP(light weight process)와 고유 번호를 확인한다. 고유 번호를 16진수로 변환하면 NID를 얻을 수 있다. 다음 예에서 CPU를 가장 많이 사용하는 LWP의 고유 번호는 10039이고, 이 번호를 16진수 변환한 숫자는 0x2737이다.
[user@linux ~]$ ps -mo pid,lwp,stime,time,cpu -C java
PID LWP STIME TIME %CPU 10029 - Dec07 00:02:02 99.5 - 10039 Dec07 00:00:00 0.1 - 10040 Dec07 00:00:00 95.5 ... |
그 다음으로 스레드 덤프를 얻어 스레드의 동작을 확인한다. 다음은 PID가 10029인 애플리케이션의 스레드 덤프이다 .이 스레드 덤프에서 NID가 0x2737인 스레드를 찾아 스레드의 동작을 확인한다.
"NioProcessor-2" prio=10 tid=0x0a8d2800 nid=0x2737 runnable [0x49aa5000] java.lang.Thread.State: RUNNABLE at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:210) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:65) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) - locked <0x74c52678> (a sun.nio.ch.Util$1) - locked <0x74c52668> (a java.util.Collections$UnmodifiableSet) - locked <0x74c501b0> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) at external.org.apache.mina.transport.socket.nio.NioProcessor.select(NioProcessor.java:65) at external.org.apache.mina.common.AbstractPollingIoProcessor$Worker.run(AbstractPollingIoProcessor.java:708) at external.org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:662) |
스레드 덤프를 시간 별로 여러 번 획득해서 스레드의 동작 상태 변화를 확인해 문제 상황을 추론해야 한다.
상황2: 수행 성능이 비정상적으로 느릴 때
애플리케이션의 수행 성능이 비정상적으로 느릴 때에는 BLOCKED 상태인 스레드가 원인인 경우가 많다. 이 때에는 스레드 덤프를 여러 번 얻은 다음 BLOCKED 상태인 스레드 목록을 찾고 BLOCKED 상태인 스레드가 획득하려는 락과 관계된 스레드를 추출해 본다.
아래 스레드 덤프 예에서는 <0xe0375410> 락을 획득하지 못해 계속 BLCOKED 상태에 있다. 해당 락을 획득하고 있는 스레드의 스택 트레이스(Stack Trace)를 분석하면 문제를 해결할 수 있다.
" DB-Processor-13" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f000] java.lang.Thread.State: BLOCKED (on object monitor) at beans.ConnectionPool.getConnection(ConnectionPool.java:102) - waiting to lock <0xe0375410> (a beans.ConnectionPool) at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111) at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
"DB-Processor-14" daemon prio=5 tid=0x003edf98 nid=0xca waiting for monitor entry [0x000000000825f020] java.lang.Thread.State: BLOCKED (on object monitor) at beans.ConnectionPool.getConnection(ConnectionPool.java:102) - waiting to lock <0xe0375410> (a beans.ConnectionPool) at beans.cus.ServiceCnt.getTodayCount(ServiceCnt.java:111) at beans.cus.ServiceCnt.insertCount(ServiceCnt.java:43)
" DB-Processor-3" daemon prio=5 tid=0x00928248 nid=0x8b waiting for monitor entry [0x000000000825d080] java.lang.Thread.State: RUNNABLE at oracle.jdbc.driver.OracleConnection.isClosed(OracleConnection.java:570) - waiting to lock <0xe03ba2e0> (a oracle.jdbc.driver.OracleConnection) at beans.ConnectionPool.getConnection(ConnectionPool.java:112) - locked <0xe0386580> (a java.util.Vector) - locked <0xe0375410> (a beans.ConnectionPool) at beans.cus.Cue_1700c.GetNationList(Cue_1700c.java:66) at org.apache.jsp.cue_1700c_jsp._jspService(cue_1700c_jsp.java:120) |
이런 패턴은 DBMS를 다루는 애플리케이션에서 자주 나타나는 데, 다음은 가장 자주 나타나는 두가지 경우이다.
첫째, 스레드가 계속 동작하고 있지만 DBCP 등의 설정이 적절하지 못해 충분한 성능을 내지 못하는 경우이다. 이 경우에는 스레드 덤프를 여러 번 얻어서 비교하면 BLOCKED 상태에 있던 스레드 중 몇 개는 다른 상태인 경우가 많을 것이다.
둘째, DBMS와 연결이 비정상적인 상태라 계속 타임아웃(timeout) 시간까지 대기하는 경우이다. 이 경우에는 스레드 덤프를 여러 번 추출해 비교해도 DBMS와 관련된 스레드는 계속해서 BLOCKED 상태에 있는 것을 확인할 수 있다. 타임아웃 값 등을 적절하게 변경해서 문제 발생 시간을 줄일 수 있다.
스레드 덤프 분석을 쉽게 만드는 코딩
스레드에 이름 부여하기
java.lang.Thread 클래스를 이용해 스레드 객체를 생성하면 Thread-(Number) 라는 형식으로 스레드 이름이 생성된다. 그리고 java.util.concurrent.DefaultThreadFactory 클래스를 이용해 스레드 객체를 생성하면 pool-(Number)-thread-(Number)라는 형식으로 스레드 이름이 생성된다.
애플리케이션당 적으면 수십 개, 많으면 수천 개가 되는 스레드를 분석할 때, 스레드 이름이 모두 이렇게 기본값으로 되어 있다면 분석 대상이 될 스레드를 구별하기 어렵게 된다. 그렇기 때문에 스레드 생성 시에는 반드시 스레드에 이름을 부여하는 습관을 가지는 것이 좋다.
java.lang.Thread 클래스를 이용해 스레드를 생성할 때에는 생성자의 인수를 이용해 스레드에 이름을 부여할 수 있다.
public Thread(Runnable target, String name);
public Thread(ThreadGroup group, String name);
public Thread(ThreadGroup group, Runnable target, String name);
public Thread(ThreadGroup group, Runnable target, String name, long stackSize);
java.util.concurrent.ThreadFactory 클래스를 이용해 스레드 객체를 생성할 때에는 자신만의 ThreadFactory 클래스를 생성해 이름을 부여하면 된다. 크게 특별한 기능이 필요하지 않다면 다음과 같은 MyThreadFactory를 사용할 수 있다.
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ThreadFactory;
import java.util.concurrent.atomic.AtomicInteger;
public class MyThreadFactory implements ThreadFactory {
private static final ConcurrentHashMap POOL_NUMBER =
new ConcurrentHashMap();
private final ThreadGroup group;
private final AtomicInteger threadNumber = new AtomicInteger(1);
private final String namePrefix;
public MyThreadFactory(String threadPoolName) {
if (threadPoolName == null) {
throw new NullPointerException("threadPoolName");
}
POOL_NUMBER.putIfAbsent(threadPoolName, new AtomicInteger());
SecurityManager securityManager = System.getSecurityManager();
group = (securityManager != null) - securityManager.getThreadGroup() :
Thread.currentThread().getThreadGroup();
AtomicInteger poolCount = POOL_NUMBER.get(threadPoolName);
if (poolCount == null) {
namePrefix = threadPoolName + " pool-00-thread-";
} else {
namePrefix = threadPoolName + " pool-" + poolCount.getAndIncrement() + "-thread-";
}
}
public Thread newThread(Runnable runnable) {
Thread thread = new Thread(group, runnable, namePrefix + threadNumber.getAndIncrement(), 0);
if (thread.isDaemon()) {
thread.setDaemon(false);
}
if (thread.getPriority() != Thread.NORM_PRIORITY) {
thread.setPriority(Thread.NORM_PRIORITY);
}
return thread;
}
}
MBean을 이용한 더 자세한 정보 획득하기
MBean을 이용하면 ThreadInfo 객체를 획득할 수 있으며, ThreadInfo 객체를 이용하면 스레드 덤프에서 얻기 힘든 정보들을 추가로 얻을 수 있다. 예를 들어, ThreadInfo 객체의 메서드를 이용해 스레드가 BLOCKED 상태나 WAIT 상태로 된 시간의 정보를 얻을 수 있고, 이를 이용해 비정상적으로 긴 시간 동안 동작하고 있지 않은 스레드 목록을 얻을 수도 있다.
ThreadMXBean mxBean = ManagementFactory.getThreadMXBean();
long[] threadIds = mxBean.getAllThreadIds();
ThreadInfo[] threadInfos =
mxBean.getThreadInfo(threadIds);
for (ThreadInfo threadInfo : threadInfos) {
System.out.println(
threadInfo.getThreadName());
System.out.println(
threadInfo.getBlockedCount());
System.out.println(
threadInfo.getBlockedTime());
System.out.println(
threadInfo.getWaitedCount());
System.out.println(
threadInfo.getWaitedTime());
}
