[Java] Thread Dump

Thread Dump란?
문제상황1. 데드락
문제상황2. 처리 지연

 

Thread Dump란?

실행 중인 서버의 thread 상태의 snapshot을 획득하는 행위를 말합니다. 앞선 글 동시성 처리 - intro에서 살펴보았듯이 멀티스레드 환경에서 발생하는 여러 이슈들이 있습니다. 각 스레드가 어떤 상태에 놓여 있는지 thread dump를 활용하여 분석하면 어디서 문제가 발생하였는지 측정하여 이를 해결할 수 있습니다.

이번 글에서는 VisualVM을 활용해 특정 문제 상황들을 재현한 뒤 thread의 상태를 분석해보도록 하겠습니다. NaverD2 - 스레드 덤프 분석하기를 보면 jstack, JMC 등을 이용해  thread dump를 뜨면 로그 형태의 text로 각 thread의 정보를 확인할 수 있는데, VisualVM을 활용하면 이를 가시적으로 확인할 수 있습니다.

이번 글에서는 데드락, 처리 지연, 스레드풀 기아(starvation) 상황을 살펴보도록 하겠습니다.

 

문제상황1. 데드락

고유 락 1과 2를 갖고 있는 Deadlock 클래스를 생성합니다. lock 1 -> 2 순서로 락을 획득하는 acquireLock12() 메서드와, lock 2 -> 1 순서로 락을 획득하는 acquireLock21() 메서드를 선언했습니다. 각 메서드는 각기 다른 스레드에서 호출할 것입니다. 이 때, acquireLock12() 메서드는 lock1을 획득하고 5초 뒤에 lock2를 획득하는 시도를 합니다. acquireLock21() 메서드는 lock2를 획득하고 3초 뒤에 lock1을 획득하는 시도를 합니다. 각 스레드가 다른 스레드에서 점유하고 있는 락을 획득하기 위해 대기해야 하므로 데드락이 발생할 것으로 예상할 수 있습니다.

public class Deadlock {

    Object lock1 = new Object();
    Object lock2 = new Object();

    public void acquireLock12() throws InterruptedException {
        synchronized (lock1) {
            Thread.sleep(5000);
            acquireLock21();
        }
    }

    public void acquireLock21() throws InterruptedException {
        synchronized (lock2) {
            Thread.sleep(3000);
            acquireLock12();
        }
    }
}

main 메서드를 통해 각 메서드를 각기 다른 스레드를 통해 실행시켜보겠습니다. main 메서드가 종료되지 않기 위해 Thread를 sleep 하는 코드를 추가하였습니다.

public class DeadlockApp {

    private static final Deadlock deadlock = new Deadlock();

    public static void main(String[] args) throws InterruptedException {
        new Thread(() -> acquireLock12()).start();
        new Thread(() -> acquireLock21()).start();

        while (true) {
            Thread.sleep(2000);
            System.out.println("waiting...");
        }
    }

    private static void acquireLock12() {
        try {
            deadlock.acquireLock12();
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

    private static void acquireLock21() {
        try {
            deadlock.acquireLock21();
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

이를 VisualVM에서 확인하면 다음과 같이 'Deadlock detected!' 메시지를 확인할 수 있습니다.

 

이제 어떤 스레드로 인해 데드락이 발생했는지 thread dump를 통해 확인해보겠습니다.

Thread-0은 Thread-1에 의해, Thread-1은 Thread-0에 의해 점유되고 있는 락을 획득하기 위해 기다리고 있는 것을 확인할 수 있습니다. 문제가 발생한 지점의 method stack 정보도 함께 제공하고 있습니다.

 

문제상황2. 처리 지연

Thread-1은 fast() 메서드를 호출해 빠르게 종료되도록 하고, Thread-0은 sleep하여 처리에 총 10초가 걸리는 slow() 메서드를 호출하게 하였습니다.

public class SlowApp {

    public static void main(String[] args) throws InterruptedException {
        new Thread(() -> callSlow()).start();
        new Thread(() -> callFast()).start();
    }

    private static void callSlow() {
        for (int i = 0; i < 10; i++) {
            try {
                Slow.slow();
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }

    private static void callFast() {
        Fast.fast();
    }
}

class Slow {
    static void slow() throws InterruptedException {
        Thread.sleep(1000);
    }
}

class Fast {
    static void fast() {}
}

 

 

VisualVM의 Thread dump를 통해 확인해보면 다음과 같이 thread의 상태를 볼 수 있습니다. Thread.sleep()을 호출하였기 때문에 dump 시점의 Thread는 cpu 점유시간(cpu=0.52ms) 자체는 적지만 상태는 'TIMED_WATING (sleeping)'으로, 스레드가 호출 후 경과시간(elapsed=7.22s)은 긴 것을 확인할 수 있습니다.

TIMED_WAITING state로 인해 처리가 지연되지 않고, 호출 메서드 자체의 처리가 지연되는 현상을 보기 위해 Long 타입의 number를 10억번 증가시키는 부하를 주도록 하겠습니다. 이 처리는 1~2초의 시간이 소요될 것입니다.

public class SlowApp {

    public static void main(String[] args) {
        new Thread(() -> callSlow()).start();
        new Thread(() -> callFast()).start();
    }

    private static void callSlow() {
        for (int i = 0; i < 10; i++) {
            Slow.slow();
        }
    }

    private static void callFast() {
        Fast.fast();
    }
}

class Slow {
    static void slow(){
        Long number = 0L;
        for (int i = 0; i < 1000000000; i++) {
            number += 1;
        }
    }
}

class Fast {
    static void fast() {}
}

VisualVM의 Thread dump를 통해 확인해보면 다음과 같이 thread의 상태를 볼 수 있습니다. Thread의 state 자체는 RUNNABLE로 실행중이지만, cpu 점유시간(cpu=14981.99ms)은 약 15초로 상대적으로 매우 긴 처리시간을 갖고 있는 것을 확인할 수 있습니다.