[Java] Jstack 을 활용한 스레드(Thread) 덤프, 리소스 모니터링

Spring boot 기반 프로젝트 내에서 Java Thread를 활용한 로직을 활용 도중 특정 스레드 에서의 병목현상이 발생하였고 해당 병목 현상을 해결하는 과정에서의 스레드 덤프를  활용하였고 많은 도움이 되었습니다.

스레드 덤프를 뜨기 위한 Jstack에 대한 기본 사용법과 활용법을 공유하고자 합니다.

 

트위터 망해도 스레드는 안..아니 언제부터 보고 계신거에요?

 

Jstack??

---

Jstack이란 JDK와 함께 제공되는 유틸리티로 Java Thread Dump를 생성하는 데 사용됩니다.

 

 

Windows와 Linux에서 jstack.exe로 Thread Dump 생성하기

---

${jdk설치경로}\bin

 

target 경로에서 jstack.exe를 활용해서 전체 Thread Dump를 추출합니다.

 

사전 시나리오

 

EndPoint

@RestController
public class PrintSomeText {

    private final TextDataService textDataService;

    public PrintSomeText(TextDataService textDataService) {
        this.textDataService = textDataService;
    }

    @GetMapping("/stock")
    public Flux<String> getStockData() {
        return textDataService.getStockData();
    }

    @GetMapping("/news")
    public Flux<String> getNewsData() {
        return textDataService.getNewsData();
    }

}

 

TextDataService

@Service
public class TextDataService {

    private final ExecutorService executorService = Executors.newFixedThreadPool(10);

    public Flux<String> getStockData() {
        List<Callable<String>> tasks = Arrays.asList(
            () -> { Thread.sleep(10000); return "Stock1"; },
            () -> { Thread.sleep(10000); return "Stock2"; },
            () -> { Thread.sleep(10000); return "Stock3"; }
        );
        return Flux.fromIterable(tasks)
            .flatMap(task -> Mono.fromCallable(task)
                .subscribeOn(Schedulers.fromExecutorService(executorService)));
    }

    public Flux<String> getNewsData() {
        List<Callable<String>> tasks = Arrays.asList(
            () -> { Thread.sleep(10000); return "News1"; },
            () -> { Thread.sleep(10000); return "News2"; },
            () -> { Thread.sleep(10000); return "News3"; }
        );
        return Flux.fromIterable(tasks)
            .flatMap(task -> Mono.fromCallable(task)
                .subscribeOn(Schedulers.fromExecutorService(executorService)));
    }
}

 

endpoint를 열어두고 service내부에서 thread를 sleep을 걸어 url 요청 후 sleep 기간 안에 jstack을 활용하여 thread 덤프를 떠보도록 하겠습니다.

 

사실 webflux를 사용할 필요는 없으나 요즘 webflux를 공부 중이기 때문에 손에 익으려고 webflux 기반으로 작성했습니다.

 

threadpool은 fixedthreadpool로 넉넉하게 10개 정도 줘서 작업했습니다.

 

실행 중인 java 애플리케이션의 pid는 어떻게 알까?

---

 

JDK에 포함되어 있는 JPS 명령어를 활용해서 JVM 내부에서 돌아가고 있는 PID를 파악합니다.

[-v] 옵션을 추가적으로 입력 시 실행 시 입력된 parameter도 확인할 수 있습니다.

 

저의 경우 pid가 69756이기 때문에 해당 PID로 스레드 덤프를 떠보도록 하겠습니다.

 

jstack -l 69756 > ${리다이렉션 시켜서 stack 파일을 떨어트리고 싶은 경로}/stack.txt

 

-l 옵션을 활용해서 stack.txt 파일을 생성해 보도록 하겠습니다.

 

-l 옵션을 사용하면, 추가로 락 정보를 출력합니다.

 

-e 옵션의 경우 error log를 좀더 상세하게 찍어서 출력해 줍니다.

스레드 덤프의 세부 정보

---

//.. 


"pool-3-thread-7" #63 [35847] prio=5 os_prio=31 cpu=0.16ms elapsed=0.97s tid=0x0000000128817400 nid=35847 waiting on condition  [0x0000000173aca000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep0(java.base@19.0.1/Native Method)
	at java.lang.Thread.sleep(java.base@19.0.1/Thread.java:465)
	at com.reactive.WebFluxPlayGround.Service.TextDataService.lambda$getNewsData$4(TextDataService.java:32)
	at com.reactive.WebFluxPlayGround.Service.TextDataService$$Lambda$1058/0x000000080145e1f0.call(Unknown Source)
	at reactor.core.publisher.MonoCallable.call(MonoCallable.java:72)
	at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:227)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	at java.util.concurrent.FutureTask.run(java.base@19.0.1/FutureTask.java:317)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@19.0.1/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@19.0.1/ThreadPoolExecutor.java:642)
	at java.lang.Thread.run(java.base@19.0.1/Thread.java:1589)

   Locked ownable synchronizers:
	- <0x00000007023970d8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"pool-3-thread-8" #64 [22027] prio=5 os_prio=31 cpu=0.10ms elapsed=0.97s tid=0x0000000128009200 nid=22027 waiting on condition  [0x0000000173cd6000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep0(java.base@19.0.1/Native Method)
	at java.lang.Thread.sleep(java.base@19.0.1/Thread.java:465)
	at com.reactive.WebFluxPlayGround.Service.TextDataService.lambda$getNewsData$5(TextDataService.java:33)
	at com.reactive.WebFluxPlayGround.Service.TextDataService$$Lambda$1059/0x000000080145e3f8.call(Unknown Source)
	at reactor.core.publisher.MonoCallable.call(MonoCallable.java:72)
	at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:227)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	at java.util.concurrent.FutureTask.run(java.base@19.0.1/FutureTask.java:317)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@19.0.1/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@19.0.1/ThreadPoolExecutor.java:642)
	at java.lang.Thread.run(java.base@19.0.1/Thread.java:1589)

   Locked ownable synchronizers:
	- <0x0000000702397560> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"pool-3-thread-9" #65 [41735] prio=5 os_prio=31 cpu=0.10ms elapsed=0.97s tid=0x0000000128009800 nid=41735 waiting on condition  [0x0000000173ee2000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
	at java.lang.Thread.sleep0(java.base@19.0.1/Native Method)
	at java.lang.Thread.sleep(java.base@19.0.1/Thread.java:465)
	at com.reactive.WebFluxPlayGround.Service.TextDataService.lambda$getNewsData$6(TextDataService.java:34)
	at com.reactive.WebFluxPlayGround.Service.TextDataService$$Lambda$1060/0x000000080145e600.call(Unknown Source)
	at reactor.core.publisher.MonoCallable.call(MonoCallable.java:72)
	at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:227)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28)
	at java.util.concurrent.FutureTask.run(java.base@19.0.1/FutureTask.java:317)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@19.0.1/ThreadPoolExecutor.java:1144)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@19.0.1/ThreadPoolExecutor.java:642)
	at java.lang.Thread.run(java.base@19.0.1/Thread.java:1589)

   Locked ownable synchronizers:
	- <0x00000007023979e8> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"VM Thread" os_prio=31 cpu=54.58ms elapsed=321.44s tid=0x000000012c80d8f0 nid=16899 runnable  

"GC Thread#0" os_prio=31 cpu=18.99ms elapsed=321.44s tid=0x000000012c806630 nid=14595 runnable

Thread dump는 dump stack이기 때문에 아래서부터 위로 호출 순서로 표시됩니다.

 

혹시 기억나시나요? 위에서

 

public Flux<String> getNewsData() {
        List<Callable<String>> tasks = Arrays.asList(
            () -> { Thread.sleep(10000); return "News1"; },
            () -> { Thread.sleep(10000); return "News2"; },
            () -> { Thread.sleep(10000); return "News3"; }
        );
        return Flux.fromIterable(tasks)
            .flatMap(task -> Mono.fromCallable(task)
                .subscribeOn(Schedulers.fromExecutorService(executorService)));
    }

세 가지 스레드에 세번 sleep을 걸어 두었습니다.

 

위 덤프 내용을 보면 thread status 가 세 가지 각각 sleep 상태임을 확인할 수 있습니다..

 

at com.reactive.WebFluxPlayGround.Service.TextDataService.lambda$getNewsData$4(TextDataService.java:32)

 

dump 정보를 보면 호출 서비스 이름, 람다다 식이라는 표현, line 정보까지 전부 확인 가능합니다.

 

cpu 속도 및 각종 상태를 확인할 수 있습니다.

 

 

윈도우 환경에서 nid(Native Thread Id)의 활용

---

윈도우 환경 내에서는 nid(Native Thread Id) 16진수로 표시된 스레드 아이디를 활용하여 해당 Thread가 cpu resource를 얼마나 점유하고 있는지를 파악할 수 있습니다.

 

Process Explorer

 

Process Explorer - Sysinternals | Microsoft Learn

Process Explorer - Sysinternals

 

시스템에서 사용하고 있는 프로세스에 대한 다양한 정보를 얻을 수 있습니다.

 

출처 : Use Windows Process Explorer to troubleshoot Jira server Performance

tomcat에서 우클릭 후 Properties를 클릭하면

 

출처 : Use Windows Process Explorer to troubleshoot Jira server Performance

 

위와 같이 해당 프로세스 내부에 thread id를 확인할 수 있습니다.

 

nid 값을 10진수로 변환 후 위와 tid와 대조해 보면 cpu리소스를 많이 먹고 있는 thread를 확인할 수 있고 해당 병목지점에 대한 파악이 수월 해집니다.

 

스레드 덤프를 통해 얻을 수 있는 이점

---

Performance Tuning

스레드 덤프는 애플리케이션 성능 튜닝에 필수적인 정보를 제공.

Deadlock Detection

스레드 덤프를 통해 애플리케이션 내의 데드락을 쉽게 발견할 수 있음.

CPU Usage Analysis

스레드 덤프는 CPU 사용률 분석에 도움이 됨.

 

thread 덤프를 출력 후 gc에서 상당 부분 소비를 하는 경우도 존재하는데 해당 경우에는 별도의 memory 덤프를 떠서 메모리 누수나 메모리를 많이 먹고 있는 특정 프로세스에 대해서 파악하시는 것을 추천드립니다.