[TroubleShooting] ThreadDump 분석 가이드

본 포스팅은 ThreadDump 분석 가이드하겠습니다.

---

ThreadDump는 현재 Working 중인 프로세스의 상세정보를 확인하는데 그 목적이 있습니다. 대체로 ThreadDump 만으로 충분한 데이터를 취득할 수도 있지만, 일반적으로는 CPU모니터링과 함께 HeapDump 분석에 유용한 자료로 활용됩니다.

 

먼저 Thread dump의 정의에 대해 알아보겠습니다.

ThreadDump는 Java(JVM)에서 사용하는 Thread들에 대한 Thread call stack 정보를 담고 있는 스냅샷이라고 볼수 있습니다.

- OS 별로 Thread에 대한 내부 구조 (스케줄링, 라이프사이클 등)이 조금씩 다르며, JVM에 영향을 미칩니다.

- OS는 Process와 Thread의 관계가 1:1 or 1:n으로 구성되어 있으며, Thread 기반으로 구현하지 않아도 기본적으로 Single Thread로 구동하도록 되어 있습니다.

- java는 이러한 멀티 Thread 들이 현재 무엇을 하고 있는지에 대한 Call stack을 손 쉽게 확인 할 수 있는 기능을 제공하며, 이것이 Thread dump입니다.

- Thread dump는 java 벤더로 구조가 조금씩 다릅니다.

 

ThreadDump 분석 전 확인 사항은 다음과 같습니다.

먼저 Thread dump를 통해 분석이 필요한 경우가 어떤 경우일까에 대해 고민해 보아야 합니다.

첫번째로 java application이 hang 상태가 될 때입니다.

Thread dump를 이용하여 트러블 슈팅 하는 가장 흔한 상황이 Hang 상태입니다.

Hang 상태는 Java application의 Thread들이 멈춰있는 상황으로 Thread Dump를 통해 Thread들이 현재 수행하는 있는 상태를 확인하는 것으로 원인을 파악할 수 있습니다.

두번째로 java application의 처리가 늦을 경우입니다.

Java application의 처리가 늦을 경우 어느 stack에서 지연되는지 확인하기 위해 활용 할 수 있습니다.

Hang은 아니나 Thread들이 sleep 단계에서 모두 대기하는 상태가 있을 수 있습니다.

SQL 문 수행의 지연으로 DB에서의 데이터를 socket read하기 위해 대기하는 상태 등을 예로 들수 있습니다.

세번째로 java application의 CPU 사용률이 높을 경우입니다.

Java application의 특정 Thread의 CPU 사용률이 높을 경우 Thread의 수행 상태와 stack을 확인하기 위해 Thread dump를 활용할 수 있습니다.

 

다음으로 thread dump 생성 방법에 대해 알아보겠습니다.

- Java process에 signal을 전달하여 생성합니다.

- Java process를 만든 벤더들이 내부적으로 SIGQUIT에 대한 signal을 catch하여 그 시점의 stack trace를 출력하는 것입니다.

- Unix 계열의 경우 kill -3 PID로 생성이 가능합니다.

- Windows 계열의 경우 ctrl+Break 키를 동시에 눌러 생성이 가능합니다.

 

ThreadDump의 생성 위치 OS 별 차이가 있습니다.

- Sun 계열 (Sun, HP-UX, Linux 등)의 경우는 Thread dump를 수행하면 STOUT으로 출력됩니다. STOUT은 표준 출력을 말합니다. 표준 출력이란 프로세스가 기본적으로 생성되는 입출력 (FD) 중의 하나입니다. WAS의 경우 로그파일에 출력되게 됩니다.

- IBM 계열의 경우 Thread dump 생성을 수행하기 위해 kill 명령을 수행하면 STDOUT으로 출력되지 않고 javacore라는 파일을 생성시켜 출력하게 됩니다. 해당 파일에 대한 위치는 "IBM_JAVACOREDIR" 이라는 환경변수 설정을 통해 디렉토리를 지정할 수 있습니다. 해당 환경변수를 설정하지 않았을 경우 javacore 파일이 생성되는 위치를 확인하기 위해서는 다음과 같은 명령을 통해 알 수 있습니다.

IBM JVM에서는 dump agent를 통해 각종 dump 파일(system dump, heap dump, snap trace, java 등)들을 생성하기 위한 설정을 제어할 수 있습니다.

- 그밖에 프로세스 debug를 위한 dbx나 프로파일 툴 Dtrace가 있습니다.

 

자 그럼 Thread dump를 직접 분석해 보겠습니다.

먼저 Sun 계열(Sun, HP-UX, Linux 등)입니다.

- thread dump 구조

Sun 계열의 java는 Thread dump가 표준출력으로 출력됩니다.

Thread에 대한 정보가 첫 라인에 출력되고 그 뒤로 Thread에 대한 stack trace 정보가 출력되는 형식입니다.

아래 thread 정보 구문에서는 Thread 명, Deamon 여부, Priority, Thread 메모리 번지(TID), Native thread id(NID), status 등이 포함되어 있습니다.

# 참조

Thread 상태 정보는 아래와 같이 여러가지 Status로 나뉠수 있습니다.

먼저 JDK 1.5입니다.

- allocated는 Thread가 생성되기 위해 메모리 할당 된 상태입니다.

- initialized는 Thread가 초기화 된 상태입니다.

- runnable는 Thread가 java virtual machine 내에서 수행 중인 상태입니다.

- waiting for monitor entry는 Thread가 Monitor lock을 획득하기 위해 대기중인 상태입니다.

Monitor lock이란 Multi thread 환경에서 thread를 동시 접근하는 것을 막아 database 부하를 줄이거나 thread 병합을 막는 역할을 합니다. 해당 lock은 synchronized 된 object에만 적용 됩니다. 정리하자면, synchronized 된 object를 현재 사용 중인지 아닌지 검사하는 것이 Monitor lock입니다.

- waiting on condition는 Thread가 조건 변수(Condition Variable)에 의해 대기 중인 상태입니다.

- in object wait()는 Thread가 Object.wait()으로 인해 대기 중인 상태입니다.

- sleeping는 Thread가 I/O등에 의해 대기 중인 SLEEP 상태가 된 경우입니다.

 

JDK 1.6은 다음과 같습니다.

- NEW는 Thread가 생성되기 위해 메모리에 할당 된 상태입니다.

- RUNNABLE는 Thread가 java virtual machine 내에서 수행 중인 상태입니다.

- BLOCKED는 Thread가 Monitor lock을 획득하기 위해 대기중인 상태입니다.

- WAITING는 Thread가 특정 작업을 위해 다른 Thread를 무기한 대기하는 상태입니다.

- TIMED_WAITING는 Thread가 특정 작업을 위해 정해진 시가만큼 다른 Thread를 대기하는 상태입니다.

- TERMINATED는 Thread가 exited 된 상태입니다.

 

실제 stack을 분석해 보자면, getPooledConnection 부분에서 object에 대한 lock을 획득하고 계속 처리하다가 getConnection에서 object lock을 획득하려고 확인 중 해당 object를 다른 Thread에 의해 lock이 걸려 있어 lock이 반환 될 때까지 대기 중인 상태입니다.

Object lock에 대한 내용을 알기 위해서는 앞서 설명 드린 동기화 부분과 object format의 lock flag에 대한 부분을 정확히 알고 있어야 위의 Thread stack에 대한 원인을 해결 할 수 있습니다.

 

다음으로 IBM 계열입니다.

Sun 계열의 경우 Thread dump 수행 시점의 간단한 Thread들의 정보와 Stack trace 정도만 제공해 주시만, IBM의 Thread dump는 수행 지점의 JVM 프로세스에 대한 매우 상세한 정보를 제공합니다.

IBM JVM subcomponent structure는 다음과 같습니다.

- CI(Core Interface)는 User, 외부 프로그램, 환경에 관련된 인터페이스를 담당합니다.

- XM(Execution Management)는 다중 수행 Multiple execution의 관리와  프로세스 control 기능을 제공합니다.

- DG(Diagnostics)는 각종 진단 기능과 서비스 디버그 기능 그리고 도구들을 제공합니다.

- XE(Execution Engine)는 Byte code를 수행하기 위한 다양한 방법을 제공합니다.

- CL(Class Loader)는 Java class들의 위한 모든 지원 기능들을 제공합니다.

- DC(Data Conversion)는 다양한 format들간의 data 변경 기능들을 제공합니다.

- LK(Lock)는 Locking과 Synchronization 서비스 기능들을 제공합니다.

- ST(Storage)는 Storage 서비스(메모리) 부분에 대한 기능들을 제공합니다.

- HPI(Hardware Platform Interface)는 Low-level facility와 다양한 platform에 대한 서비스에 대한 기능들을 제공합니다.

 

ThreadDump Tag는 다음과 같이 구성됩니다.

- 최대 15자리의 문자로 구성되어 있습니다.
- 첫번째 숫자는 각 구성요소의 순번을 의미합니다.
- 2~3번째 문자는 Section 정보를 의미합니다.
- 나머지는 출력라인에 대한 정보 문자입니다.
- 0SECTION Tag는 모든 Section의 시작을 의미합니다.

- NULL은 공백 라인에 대한 Tag 입니다.

 

# 참조

thread state는 다음과 같은 상태를 갖을 수 있습니다.

- R는 Runnable는 Thread가 수행 가능한 상태(Run queue 진입)입니다.
- CW는 Condition Wait는 Thread가 wait 상태(sleep, I/O block, lock에 대한 wait등)입니다.
- S는 Suspended는 Thread가 다른 Thread에 의해 중지된 상태입니다.
- Z는 Zombie는 Thread가 kill 된 상태입니다.
- P는 Parked는 Concurrency API(java.util.concurrent)에 의해 park된 상태입니다.
- B는 Blocked는 Thread가 동기화 모듈을 통해 lock을 획득하기 위해 대기중인 상태입니다.

 

Java stack trace를 봤을 때 OutOfMemoryError를 받아 error를 Throwable하고 있는 상태입니다. 그 사이에 VirtualMachineError가 발생하였습니다. 해당 error가 발생할 수 있는 이유는 대체적으로 2가지 인데 가비지 컬렉터가 새로운 객체를 생성 할 공간을 더 이상 만들지 못하고, 힙 영역 메모리도 늘어 날 수 없을 때 또는 네이티브 라이브러리 코드에서 스왑 영역이 부족하여 네이티브 할당을 더 이상 할 수 없을 때 발생 합니다.

실제로 해당 stack외에 application stack이 발생하였을 경우 해당 stack에 대한 heap dump 분석 역시 병행 하면 보다 정확한 분석이 될 수 있습니다.

 

자 마지막으로 Thread dump 상세 분석 결과를 가이드 드리겠습니다.

먼저 Object Locking입니다.

- Object locking은 java 기반의 program에서 shared resource에 접근 할 경우 Lock을 획득하며, 또한 이러한 Lock을 다른 Thread들이 이미 획득하고 있을 경우 Lock을 획득하기 위해 대기합니다. Java에서의 Lock은 내부 Monitor를 통해 구현되고 관리됩니다. 즉 Monitor 획득이 Lock 획득을 의미 합니다. 이렇게 Lock을 획득하기 위해 대기하는 Thread들이 많아 지고, 대기시간이 길어지면 Hang인 것처럼 보여지게 됩니다.

Java program에서 Lock을 획득하기 위해서는 Synchronized 구문을 이용하여 method 또는 lock을 획득 할 수 있습니다.

Synchronized 구문을 사용할 때 어느 부분에 사용하느냐에 따라 lock 범위와 lock 의 대상 object들이 다르게 나타납니다.

예를 들어 보자면, thread 10개가 있는 java 프로그램이 있습니다. 그리고 동기화가 필요한 메소드가 있어 synchronized를 구현하였습니다. 각 thread들이 해당 synchronized가 구현된 객체를 각각 생성하고 수행한다면 해당 synchronized가 처리된 메소드는 동기화가 이루어 지지 않습니다.

각 thread들이 synchronized가 구현된 객체를 생성하게 되면 lock flag가 각각 생성되게 됩니다.

 

두번째로 lock을 획득하지 못하는 경우 (BLOCKED)입니다.

한 thread가 lock을 소유하고 있어 다른 thread가 lock을 획득하지 못해 애플리케이션의 전체적인 성능이 느려지는 경우입니다.

 

세번째로 데드락 상태인 경우입니다.

thread A가 작업을 계속하려면 thread B가 소유한 lock을 획득해야 하고, thread B가 작업을 계속하려면 thread A가 소유한 lock을 획득해야 해서 deadlock 상태에 있는 경우입니다.

 

네번째로 Hang 상태와 CPU 과부하 원인 분석입니다.

원격 서버로부터 메시지 수신을 받기 위해 계속 대기하는 경우입니다.

thread가 계속 RUNNABLE 상태에 있어 문제가 될 만한 부분이 없는 것처럼 보이지만 thread dump를 시간 순으로 나열하면, socketReadThread thread가 계속 소켓을 읽으려 무한정으로 대기하고 있는 상태입니다.

thread 들이 모두 지연되어 thread dump를 수행한 결과 모두가 socket read 상태에서 지연 중임을 알 수 있습니다.

특정 jsp가 수행되면서 처리 시 실제 업무 비즈니스 로직 처리를 위해 HTTP 통신을 통해 다른 서버로 요청을 전송하고 결과값을 받는 시스템입니다. 이 경우는 해당 시스템의 문제가 아니라 상대방 시스템의 처리 지연으로 발생한 경우 입니다.

 

마지막으로 WAIT 상태에 있는 경우 입니다.

Thread가 계속 WAIT 상태를 유지하고 있는 경우입니다.

다음 thread dump 예에서 IoWaitThread Thread는 LinkedBlockingQueue 객체에서 메시지를 획득하기 위해 계속 대기하고 있습니다. 만약 계속 LinkedBlockingQueue에 메시지가 들어오지 않는 다면 해당 Thread의 상태가 바뀌지 않게 됩니다.

 

자 그럼 예제를 하나 살펴보겠습니다. 

서비스가 느려지는 현상이 있어 해당 시간동안에 Thread dump를 수집한 경우입니다. 

IBM Thread and Monitor Dump Analyzer for Java 를 사용하여 분석해보겠습니다.

먼저 Thread Status Analysis 통계를 보겠습니다. 

Runnable인 Thread가 17%를 차지하였고, Wating on condition상태의 Thread가 75%를 차지하고있습니다. 

그럼 먼저 Runnable 상태의 Thread부터 살펴보겠습니다. 

ajp-thread-pool-thread 25번 에서 현재 0x00000005c12d7c10 에 대한 Monitor lock을 소유하고 있습니다.

해당 자원을 기다리는 Thread들이 2개가 있군요. (117번과 143번입니다.)

다른 Thread를 확인해봅시다. 

ajp-thread-pool-thread 33번 에서 현재 0x00000007b2f5b1f8에 대한 Monitor lock을 소유하고 있습니다.

해당 자원을 기다리는 Thread들이 6개나 있네요. 

그럼 해당 Waiting Thread들중 하나를 살펴보겠습니다. 

ajp-thread-pool-thread 33번에 의해 block되어있는 상태이며, lock을 획득하기를 기다리고 있습니다. 

다시 runnable 상태의 Stack Trace를 살펴보겠습니다.

해당 Stack Trace는 사용자 application의 코드도 확인되며, 이로인해 jboss에서 logmanager를 통해 로깅을 하는 시점에서 Thread dump가 수집된것으로 보입니다. 우선적으로 관련이 있어보이는 사용자 application의 각 클래스와 메소드들이 어떤 역할을 하는지 어느정도 파악하고 있어야 문제의 원인을 찾을수가 있습니다. 따라서 각 업무 담당자와 시스템 운영자와의 면담과 협업은 필수입니다. 

at java.util.Arrays.copyOf(Arrays.java:3332)  at java.lang.AbstractStringBuilder.ensureCapacityInternal(AbstractStringBuilder.java:124)  at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:472)  at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:486)  at java.lang.StringBuilder.append(StringBuilder.java:166)  at org.jboss.logmanager.formatters.Formatters$JustifyingFormatStep.render(Formatters.java:250)  at org.jboss.logmanager.formatters.MultistepFormatter.format(MultistepFormatter.java:83)  at org.jboss.logmanager.ExtFormatter.format(ExtFormatter.java:32)  at org.jboss.logmanager.handlers.WriterHandler.doPublish(WriterHandler.java:46)  at org.jboss.logmanager.ExtHandler.publish(ExtHandler.java:76)  at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:302)  at org.jboss.logmanager.LoggerNode.publish(LoggerNode.java:310)  at org.jboss.logmanager.Logger.logRaw(Logger.java:719)  at org.jboss.logmanager.Logger.log(Logger.java:504)  at org.jboss.stdio.StdioContext$DelegatingPrintStream.println(StdioContext.java:486)  at java.lang.Throwable$WrappedPrintStream.println(Throwable.java:748)  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:697)  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)  at java.lang.Throwable.printEnclosedStackTrace(Throwable.java:709)  at java.lang.Throwable.printStackTrace(Throwable.java:667)  - locked [0x00000005c12d7c10] (a org.jboss.stdio.StdioContext$2)  at java.lang.Throwable.printStackTrace(Throwable.java:643)  at java.lang.Throwable.printStackTrace(Throwable.java:634)  at com.kkm.common.util.ISBPUtil.objToJson(ISBPUtil.java:94) at com.kkmcommon.util.ISBPUtil.listToJsonArr(ISBPUtil.java:73)  at com.kkm.isbp.com.mail.ui.MailController.getCommCodeMail(MailController.java:86)  at com.kkm.isbp.com.mail.ui.MailController.writeMail(MailController.java:219)

ThreadDump는 현재 WAS의 Thread 들이 어떠한 일을 하고 있는지 요약정보를 보여주는 Dump입니다. 

다양한 Dump를 분석하고 이를 해결해 나가는 경험이 누적 될 때 진정한 Dump 분석가로 나아가지 않을까 싶습니다.

고맙습니다.