불과 한 달 전에는 Kafka Pub 로직이 워커 스레드 풀에서 동기 방식으로 동작하면서, Kafka 장애 발생 시 타임아웃이 날 때까지 스레드가
timed waiting상태에 머무는 문제가 있었다. 그 결과 컨테이너가 무한 재기동되는 상황이 발생했다.그런데 이번에는
FeignClient를 통한 외부 MSA 서비스 호출에서 응답 지연이 발생하면서 컨테이너가 재기동되었다. 하지만 이전과 달리 timed waiting 상태의 스레드가 늘어나지는 않았다. 그렇다면 이번에는 어떤 과정을 통해 Feign 호출 응답 지연이 컨테이너 재기동으로 이어졌는지를 정리하려 한다. 그 과정에서 JVM까지 파헤쳐봤다!
1. 장애 원인 분석 배경
사용자를 인증하는 서비스에 장애가 발생했다.
내가 담당하는 서비스는 해당 인증서비스를 FeignClient로 호출하여 유효한 사용자가 맞는지 인증하는 로직이 구현되어 있다. 그래서 인증서비스를 호출할 때마다 Time Out 혹은 응답 지연이 발생하였고, Feign Client는 워커스레드 풀에서 실행되기 때문에 Time Out/지연이 발생할 때마다 해당 시간만큼 워커스레드가 점유가 되었을 것이다.
그래서 나는 당연히 이전에 카프카 장애 발생 상황(해당 글)과 동일하게 스레드들이 timed waiting 상태에 빠졌을 것이라고 생각했다. 근데 컨테이너 재기동시점에 timed waiting 상태의 스레드가 극소수였다. 하지만 Runnable 상태의 스레드가 급증했다. 이게 어떻게 된 일일까?
2. 장애 원인 재분석
나의 예상이 틀렸다는 것을 알게 되었을 때, 혹시 재기동이 다른 원인에 있지 않을지 생각해봤다. 하지만 쿠베 이벤트 로그상, readiness probe failed 가 발생했고, 해당 시간대의 metric 지표상에 특이점 또한 없었다. 즉, 이전 카프카 장애 상황과 동일했다.
다만, 다른 점이 있다면, 이번에는 카프카가 아닌 FeignClient 호출의 지연이었다는 점이다.
그래서 나의 공부 친구 GPT랑 티키타카좀 했다. (처음에는 metric 수집 지표가 15초주기 간격이라 블랙박스때문에 timed waiting 스레드가 수집되지 않는 것이 아닐까 생각했다.)
통 답변은 다음과 같다. (한줄 요약은 맨 마지막에!)
좋은 관찰이에요 👀
말씀하신 “Feign 호출이 10초 이상 블로킹인데 Grafana에서 Timed Waiting 스레드 수가 눈에 띄게 안 늘어난다” 현상은 여러 가지 이유가 있을 수 있습니다. 하나씩 짚어드릴게요.
- JVM 스레드 상태와 모니터링 지표의 간극
Feign은 기본적으로 블로킹 HTTP 호출을 하므로, 응답 대기 동안 호출 스레드는 WAITING 또는 TIMED_WAITING 상태에 들어갑니다.
(예: Object.wait(), LockSupport.parkNanos() 같은 메서드 내부에서 잡힘)그런데 메트릭 수집기는 “샘플링” 방식이라서, 15초 간격으로 스레드 덤프 비슷한 스냅샷을 떠서 집계합니다.
만약 그 시점에 운 좋게(?) 블로킹 중인 스레드가 잡히지 않으면, 실제로는 수십 개가 대기 중이더라도 지표에 안 보일 수 있습니다.
👉 즉, 수집 주기가 길면 "스파이크"성 상태는 놓치기 쉽다는 게 첫 번째 이유예요.
- Worker 스레드 풀 크기와 관측치
Undertow의 Worker 풀은 보통 coreThreads 이상일 때는 큐잉 → idle 스레드 사용하는 구조예요.
Feign 대기가 길어도 풀 사이즈가 충분히 크면 단순히 “대기 중 스레드 수”가 크게 늘어나 보이지 않을 수 있습니다.
즉, 늘어나더라도 전체 스레드 수 대비 비율이 작아 메트릭 대시보드에서 눈에 띄지 않는 것일 수도 있어요.
- 지표 수집 방식 차이
jvm.threads.states 같은 Micrometer/Prometheus 지표는 스레드 상태별 갯수를 계수합니다.
그런데 Feign 내부가 반드시 TIMED_WAITING만 쓰는 건 아니고, RUNNABLE + 소켓 read 블로킹 상태일 수 있어요.
즉, OS 레벨에서 보면 소켓 read 대기지만, JVM은 그냥 RUNNABLE로 찍혀서 "Waiting 스레드"로는 안 잡힐 수도 있습니다.
특히 HttpURLConnection 기반은 native socketRead0()에서 블록 → JVM 레벨에서는 RUNNABLE 상태로 분류되는 경우가 흔합니다.
👉 그래서 “내가 예상한 TIMED_WAITING 스레드 수”와 JVM 지표 간에 괴리가 생겨요.
- 결론적으로
수집 주기 문제: 15초 간격이라 스파이크성 대기 상태를 놓칠 수 있음.
스레드 상태 분류 문제: Feign의 블로킹은 RUNNABLE로 보일 수 있어 TIMED_WAITING에 안 잡힘.
풀 크기 문제: Worker 풀 여유가 크면 단순히 “대기 스레드가 많다”는 현상이 시각적으로 안 보일 수 있음.
✅ 체크해보실 것
스레드 덤프 직접 떠보기 (jstack / jcmd) → 정말로 어떤 상태로 블로킹되는지 확인 (RUNNABLE vs TIMED_WAITING)
수집 주기 줄이기 (예: 5초) → 더 세밀하게 스파이크 잡힘
대기 큐 길이/사용률 지표도 같이 모니터링 → 스레드 상태만 보는 것보다 원인 파악이 쉬움
👉 그래서 질문 주신 대로 “15초 인터벌 수집 때문에 안 보이는 걸까?” → 네, 가능성이 높습니다.
다만 근본적으로는 Feign의 블로킹이 JVM 레벨에서 RUNNABLE로 찍히는 경우가 많아서, TIMED_WAITING 스레드 수가 안 늘어나는 건 정상적인 현상일 수도 있어요.
근본적으로, Feign의 Blocking이 JVM 레벨에서 Runnable로 찍힌다...?
이 답변을 보고 띄용했다. 운영체제 시간에 배운 바로는, 네트워크 I/O호출시 waiting상태에 빠진다고 들었는데 Feign Client 호출 응답 지연시 Runnable 상태라니.. 말이 안된다고 생각했다. Runnable은 엄밀히 CPU에 의해서 실행되고 있는 스레드를 말하는 것이 아닌가??
3. Thread Dump 떠보기
보고도 믿기질 않아서, 정말로 Feign 호출 응답 지연 상황 발생시, JVM의 스레드 상태를 알아 보기로 했다. 마찬가지로 Kafka pub 호출 지연 상황 발생시에도 같은 과정을 반복해보았다.
구현 코드 : 커밋 링크
(1) Feign
준비 과정
- Feign 호출 서버
- Feign 응답 서버 (Thread sleep로직을 추가하여 호출 서버의 응답 지연 상황 재현)
- 지연 상황 발생중 호출 서버의 PID로 Thread dump
결과
(참고) 스레드 명이 XNIO-1 task-N 으로 보이는 것은 undertow 웹 서버를 사용했기 때문이다.
"XNIO-1 task-9" #67 [65027] prio=5 os_prio=31 cpu=14.32ms elapsed=270.26s tid=0x0000000125862c00 nid=65027 runnable [0x0000000174253000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Net.poll(java.base@21.0.5/Native Method)
at sun.nio.ch.NioSocketImpl.park(java.base@21.0.5/NioSocketImpl.java:191)
at sun.nio.ch.NioSocketImpl.timedRead(java.base@21.0.5/NioSocketImpl.java:280)
at sun.nio.ch.NioSocketImpl.implRead(java.base@21.0.5/NioSocketImpl.java:304)
at sun.nio.ch.NioSocketImpl.read(java.base@21.0.5/NioSocketImpl.java:346)
at sun.nio.ch.NioSocketImpl$1.read(java.base@21.0.5/NioSocketImpl.java:796)
at java.net.Socket$SocketInputStream.read(java.base@21.0.5/Socket.java:1099)
at java.io.BufferedInputStream.fill(java.base@21.0.5/BufferedInputStream.java:291)
at java.io.BufferedInputStream.read1(java.base@21.0.5/BufferedInputStream.java:347)
at java.io.BufferedInputStream.implRead(java.base@21.0.5/BufferedInputStream.java:420)
at java.io.BufferedInputStream.read(java.base@21.0.5/BufferedInputStream.java:399)
at sun.net.www.http.HttpClient.parseHTTPHeader(java.base@21.0.5/HttpClient.java:827)
at sun.net.www.http.HttpClient.parseHTTP(java.base@21.0.5/HttpClient.java:759)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(java.base@21.0.5/HttpURLConnection.java:1705)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(java.base@21.0.5/HttpURLConnection.java:1614)
at java.net.HttpURLConnection.getResponseCode(java.base@21.0.5/HttpURLConnection.java:531)
at feign.Client$Default.convertResponse(Client.java:114)
at feign.Client$Default.execute(Client.java:110)
at feign.SynchronousMethodHandler.executeAndDecode(SynchronousMethodHandler.java:92)
at feign.SynchronousMethodHandler.invoke(SynchronousMethodHandler.java:53)
at feign.ReflectiveFeign$FeignInvocationHandler.invoke(ReflectiveFeign.java:104)
at my.playground.playing.threadstateonjvm.$Proxy82.slow(Unknown Source)
at my.playground.playing.threadstateonjvm.FeignController.test(FeignController.java:17)
at java.lang.invoke.LambdaForm$DMH/0x00000070015ec400.invokeVirtual(java.base@21.0.5/LambdaForm$DMH)
at java.lang.invoke.LambdaForm$MH/0x00000070015f2c00.invoke(java.base@21.0.5/LambdaForm$MH)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.5/Invokers$Holder)
at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@21.0.5/DirectMethodHandleAccessor.java:154)
at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@21.0.5/DirectMethodHandleAccessor.java:103)
at java.lang.reflect.Method.invoke(java.base@21.0.5/Method.java:580)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:258)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:191)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:986)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:891)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:903)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:527)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:276)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:132)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:256)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:101)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:395)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:861)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1538)
at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
at java.lang.Thread.runWith(java.base@21.0.5/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.5/Thread.java:1583)주목할 부분은 다음과 같다.
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.Net.poll(java.base@21.0.5/Native Method)
at
...
my.playground.playing.threadstateonjvm.FeignController.test(FeignController.java:17)
실제로 Feign 호출의 응답 지연동안, JVM 스레드가 RUNNABLE 상태라는 사실을 볼 수 있다.
(2) Kafka
준비 과정
- Kafka pub 호출 서버 (워커스레드풀 실행) ++ Springframework.kafka.core 라이브러리 사용
- Kafka 연결되지 않게 설정 (본인은 ACL로 pub시 AuthException 떨어지게 설정하였음)
- 지연 상황 발생중 호출 서버의 PID로 Thread dump
결과
"XNIO-1 task-43" #103 [54019] prio=5 os_prio=31 cpu=0.54ms elapsed=32.83s tid=0x000000010f1a2000 nid=54019 in Object.wait() [0x000000017b14b000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait0(java.base@21.0.5/Native Method)
- waiting on <0x00000006824004e0> (a org.apache.kafka.clients.producer.internals.ProducerMetadata)
at java.lang.Object.wait(java.base@21.0.5/Object.java:366)
at org.apache.kafka.common.utils.SystemTime.waitObject(SystemTime.java:55)
- locked <0x00000006824004e0> (a org.apache.kafka.clients.producer.internals.ProducerMetadata)
at org.apache.kafka.clients.producer.internals.ProducerMetadata.awaitUpdate(ProducerMetadata.java:120)
- locked <0x00000006824004e0> (a org.apache.kafka.clients.producer.internals.ProducerMetadata)
at org.apache.kafka.clients.producer.KafkaProducer.waitOnMetadata(KafkaProducer.java:1176)
at org.apache.kafka.clients.producer.KafkaProducer.doSend(KafkaProducer.java:1025)
at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:991)
at org.springframework.kafka.core.DefaultKafkaProducerFactory$CloseSafeProducer.send(DefaultKafkaProducerFactory.java:1103)
at org.springframework.kafka.core.KafkaTemplate.doSend(KafkaTemplate.java:852)
at org.springframework.kafka.core.KafkaTemplate.observeSend(KafkaTemplate.java:820)
at org.springframework.kafka.core.KafkaTemplate.send(KafkaTemplate.java:597)
at my.playground.playing.threadstateonjvm.KafkaController.pub(KafkaController.java:19)
at java.lang.invoke.LambdaForm$DMH/0x00000070011b9c00.invokeVirtual(java.base@21.0.5/LambdaForm$DMH)
at java.lang.invoke.LambdaForm$MH/0x0000007001109000.invoke(java.base@21.0.5/LambdaForm$MH)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.5/Invokers$Holder)
at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@21.0.5/DirectMethodHandleAccessor.java:154)
at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@21.0.5/DirectMethodHandleAccessor.java:103)
at java.lang.reflect.Method.invoke(java.base@21.0.5/Method.java:580)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:258)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:191)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:118)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:986)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:891)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1089)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:914)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:547)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:67)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at io.undertow.servlet.handlers.RedirectDirHandler.handleRequest(RedirectDirHandler.java:68)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:117)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.SendErrorPageHandler.handleRequest(SendErrorPageHandler.java:52)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:276)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:135)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:132)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:256)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:101)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:395)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:861)
at org.jboss.threads.ContextHandler$1.runWith(ContextHandler.java:18)
at org.jboss.threads.EnhancedQueueExecutor$Task.run(EnhancedQueueExecutor.java:2513)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1512)
at org.xnio.XnioWorker$WorkerThreadFactory$1$1.run(XnioWorker.java:1282)
at java.lang.Thread.runWith(java.base@21.0.5/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.5/Thread.java:1583)주목할 부분은 다음과 같다.
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait0(java.base@21.0.5/Native Method)
...
- locked <0x00000006824004e0> (a org.apache.kafka.clients.producer.internals.ProducerMetadata)
...
at my.playground.playing.threadstateonjvm.KafkaController.pub(KafkaController.java:19)
실제로 Kafka Pub 지연동안, TimedWating 상태임을 알 수 있다.
JVM의 스레드 상태가 OS와 일치하지 않는 이유
왜 JVM은 Feign 호출 응답 지연을 Runnable 상태라고 인지하는 걸까? Kafka는 또 왜 Timed Waiting 상태일까?
공식 문서에 따르면 Runnable 상태여도 OS에서 다른 자원을 기다리고 있을 수도 있다고(waiting 상태) 한다.
Feign 지연시, 실제로 Thread가 멈춰 있는 곳은 sun.nio.ch.Net.poll 부분이다. 이는 JNI메서드이다.
반면 Kafka 지연시, 실제로 Thread가 멈춰 있는 곳은
java.lang.Object.wait0 부분이다. 이는 Java API이다.
JNI가 필요한 이유.
JNI는 실제로 JVM에서 OS 커널로 명령어를 보내기 위한 메서드이다. OS syscall은 반드시 어셈블리로 실행되어야 할테고, 이를 C/C++ 메서드로 변환해주는 것이 JNI의 역할이다. (JNI → C → syscall)
왜 네이티브 메서드를 사용하면 Runnable 상태로 인지할까?
JVM은 네이티브 메서드가 호출된 이후에 무엇을 하는지는 알 수 없다. 그 뒷 일은 운영체제의 일이기 때문이다.
그래서 실제로 OS level에서의 스레드의 상태는 waiting일지 몰라도, JVM level의 상태는 RUNNABLE일 수 있을 것이라고 정리할 수 있다.
Java API (kafka) 내에서는..
Kafka pub이 지연된 스레드의 마지막 호출 스택 트레이스는 Object.wait 메서드로, 이는 자바 API이다.
실제로 JVM위에서 런타임에 스레드가 wait하고 있는 상태이기 때문에 JVM은 이를 timed_waiting 상태라고 인지할 수 있는 것이다.
교훈
JVM과 OS에서의 스레드 상태는 다를 수도 있다.
JAVA API가 아닌, syscall 레벨에서 동작하는 스레드는 JVM위에서는 RUNNABLE상태이다.
참고
https://docs.oracle.com/en/java/javase/24/docs/api/java.base/java/lang/Thread.State.html
