[Java] jstack 사용법 - 스레드 덤프 생성

멀티 스레드 자바 애플리케이션의 경우, 수 십개의 스레드가 공유 자원에 접근을 하면서 락(lock)을 잡았다 놓았다 한다. 이 과정에서 데드락(Dead lock)이 발생하면서 시스템이 실행을 멈추는 경우가 발생할 수 있다. 혹은 속도가 느린 외부 서버에 대한 연결 요청에 대해 기다리면서 응답시간이 늦어지는 경우도 있다.

애플리케이션의 실행이 어디에서 지체되고 있는지, 어느 부분에서 막혀있는지 확인하기 위해서는 스레드 덤프를 분석해야한다.

스레드 덤프를 생성하는 방법에는 여러가지가 있지만 이번 포스트에서는 jstack을 이용해보겠다.

설치

jstack은 JDK 패키지에 기본 포함되어 있다. 따라서 ${JAVA_HOME} 경로의 bin 디렉토리만 ${PATH}로 잡아주면 실행할 수 있다. (JAVA 5 이상 버전에 해당한다)

사용법

jstack의 사용법은 다음과 같다.

$ jstack ${PID}

jstack 명령의 인자로 실행중인 자바 애플리케이션의 PID (Process ID)를 입력해주면 된다. 자바 애플리케이션의 PID는 jps 명령으로 알 수 있다.

$ jps -v

jps -v 명령을 실행하면 현재 로그인 중인 사용자가 실행한 자바 애플리케이션들의 pid 값과 실행했을 때 넣었던 인자들도 확인할 수 있다.

일반적으로 jstack 명령은 4~5회 일정 간격을 두고 실행하는 것이 좋다. 스레드가 코드의 어느 한 부분에서 막혀있다면 4~5회의 스레드 덤프 모두에서 동일한 곳이 나올 것이기 때문이다.

덤프 해석

다음 자바 프로그램을 실행해보자.

public class Example {

    public static void main(String[] args) throws InterruptedException {

        for (int i = 0; i < 100; i++) {

            Thread.sleep(1000);
            System.out.println(i);
        }
    }
}

100초 동안 Sleep 하는 코드다.

jps -v 명령으로 pid를 알아온다.

$ jps
82857 Example
82860 Jps

그리고 jstack에 pid를 입력하고 출력되는 결과를 파일로 떨군다.

$ jstack 82857 > out

생성된 스레드 덤프 파일은 다음과 같은 내용을 포함하고 있다.

2021-06-30 08:15:39
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

"Attach Listener" #9 daemon prio=9 os_prio=31 tid=0x00007fafeb04d800 nid=0x4003 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #8 daemon prio=9 os_prio=31 tid=0x00007fafeb814800 nid=0x4403 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread2" #7 daemon prio=9 os_prio=31 tid=0x00007fafea816800 nid=0x3503 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" #6 daemon prio=9 os_prio=31 tid=0x00007fafea810000 nid=0x4603 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=31 tid=0x00007fafea021800 nid=0x4703 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fafea020800 nid=0x3303 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fafeb00f800 nid=0x2c03 in Object.wait() [0x0000700007128000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab08ed0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
    - locked <0x000000076ab08ed0> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
    at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)

"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fafea018800 nid=0x5203 in Object.wait() [0x0000700007025000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(Native Method)
    - waiting on <0x000000076ab06bf8> (a java.lang.ref.Reference$Lock)
    at java.lang.Object.wait(Object.java:502)
    at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
    - locked <0x000000076ab06bf8> (a java.lang.ref.Reference$Lock)
    at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

"main" #1 prio=5 os_prio=31 tid=0x00007fafeb00b800 nid=0xf03 waiting on condition [0x0000700006a13000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at Example.main(Example.java:7)

"VM Thread" os_prio=31 tid=0x00007fafea00f800 nid=0x2b03 runnable 

"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fafeb809000 nid=0x1907 runnable 

"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fafeb809800 nid=0x1b03 runnable 

"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fafeb00e000 nid=0x1d03 runnable 

"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fafeb00e800 nid=0x2a03 runnable 

"VM Periodic Task Thread" os_prio=31 tid=0x00007fafea810800 nid=0x4203 waiting on condition 

JNI global references: 5

JVM에는 여러 스레드들이 있다.

"main" #1 prio=5 os_prio=31 tid=0x00007fafeb00b800 nid=0xf03 waiting on condition [0x0000700006a13000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
    at java.lang.Thread.sleep(Native Method)
    at Example.main(Example.java:7)

이 중에 main 스레드의 내용을 보면, Thread.sleep()에서 멈춰있는 스택을 볼 수 있다. 만약 코드의 어떤 부분에서 스레드가 막혀있다면 동일한 부분에서 스레드 스택이 찍혀있을 것이다.