pinned virtual thread 확인하기

기록 용도로 작성한 포스트로, 올바르지 않은 내용이 포함되어 있을 수 있습니다. 

 tracePinnedThreads

자바는 pinned virtual thread를 모니터할 수 있는 시스템 프로퍼티인 tracePinnedThreads를 제공한다.

 tracePinnedThreads=full 옵션을 주면, pinned 가상 스레드를 볼 수 있다. 아래 코드를 가상 스레드로 실행시켜보자.

 

    private synchronized void call() throws InterruptedException {
        Thread.sleep(100);
        log.info("{}", Thread.currentThread());
    }

 

2025-03-01T00:11:24.407+09:00  INFO 75760 --- [mohago-nocar] [192.168.219.108] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2025-03-01T00:11:24.409+09:00  INFO 75760 --- [mohago-nocar] [192.168.219.108] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
VirtualThread[#83,tomcat-handler-0]/runnable@ForkJoinPool-1-worker-1 reason:MONITOR
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
    java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:635)
    java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:807)
    java.base/java.lang.Thread.sleep(Thread.java:507)
    com.example.mohago_nocar.plan.presentation.TestController.call(TestController.java:109) <== monitors:1
    com.example.mohago_nocar.plan.presentation.TestController.test2(TestController.java:104)
    java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
    java.base/java.lang.reflect.Method.invoke(Method.java:580)
    org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:255)
    org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:188)
    org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
    org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:926)
    org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:831)
    ...

tracePinnedThreads=full 옵션답게 로그가 길다.

 

tracePinnedThreads=short를 줘보자.

2025-03-01T00:31:57.932+09:00  INFO 54308 --- [mohago-nocar] [192.168.219.108] o.s.web.servlet.DispatcherServlet        : Completed initialization in 2 ms
VirtualThread[#85,tomcat-handler-0]/runnable@ForkJoinPool-1-worker-1 reason:MONITOR
    com.example.mohago_nocar.plan.presentation.TestController.call(TestController.java:109) <== monitors:1

tracePinnedThreads=short 답게 로그가 짧다.

 

참고로, 인텔리제이를 사용하면 아래 화면에서 편리하게 tracePinnedThreads 프로퍼티를 설정할 수 있다.

 

jcmd

$ jcmd
57912 jdk.jcmd/sun.tools.jcmd.JCmd
...
79224 com.example.mohago_nocar.MohagoNocarApplication

jcmd 79224 Thread.dump_to_file -format=json dump.json

jcmd를 이용하여 thread dump를 떠보아 가동중인 어플리케이션의 스레드 스택 트레이스를 확인할 수 있다.

 

         {
           "tid": "258",
           "name": "tomcat-handler-32",
           "stack": [
              "java.base\/java.lang.VirtualThread.park(VirtualThread.java:596)",
              "java.base\/java.lang.System$2.parkVirtualThread(System.java:2643)",
              "java.base\/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)",
              "java.base\/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)",
              "java.base\/java.util.concurrent.FutureTask.awaitDone(FutureTask.java:500)",
              "java.base\/java.util.concurrent.FutureTask.get(FutureTask.java:190)",
              "com.example.mohago_nocar.plan.presentation.TestController.lambda$planTravelCourse$5(TestController.java:78)",
              "java.base\/java.util.stream.IntPipeline$1$1.accept(IntPipeline.java:180)",
              "java.base\/java.util.stream.Streams$RangeIntSpliterator.forEachRemaining(Streams.java:104)",
              ...

이와 같은 스택 트레이스를 통해 많은 정보를 확인할 수 있다.

 

https://fastthread.io/ft-dashboard.jsp 와 같은 사이트에 해당 dump 파일을 넣으면 아래와 같은 분석 파일을 받아볼 수 있다.

 

+ virtualVM과 같은 모니터링 툴을 이용해서 thread dump를 떠보았을 때도 다음과 같은 내용을 볼 수 있었다.

"ForkJoinPool-1-worker-12" #117 [25628] daemon prio=5 os_prio=0 cpu=15.62ms elapsed=6.96s tid=0x0000018ddfe71520 nid=25628 waiting on condition  [0x0000004202cfe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@21.0.5/Native Method)
        - parking to wait for  <0x000000070843c2c0> (a java.util.concurrent.ForkJoinPool)
        at java.util.concurrent.ForkJoinPool.awaitWork(java.base@21.0.5/ForkJoinPool.java:2145)
        at java.util.concurrent.ForkJoinPool.runWorker(java.base@21.0.5/ForkJoinPool.java:2036)
        at java.util.concurrent.ForkJoinWorkerThread.run(java.base@21.0.5/ForkJoinWorkerThread.java:187)

   Locked ownable synchronizers:
        - None