Server Response 가 응답이 너무 느리거나 문제가 있어서 Thread Dump 를 생성을 해봤는데 다음과 같이 Lock 이 걸려있었다.
java.lang.Thread.State: RUNNABLE
at java.security.Provider.getService(Provider.java:667)
- locked <0x00000000a8092130> (a sun.security.provider.Sun)
at sun.security.jca.ProviderList$ServiceList.tryGet(ProviderList.java:419)
at sun.security.jca.ProviderList$ServiceList.access$200(ProviderList.java:358)
at sun.security.jca.ProviderList$ServiceList$1.hasNext(ProviderList.java:468)
at javax.crypto.KeyGenerator.a(DashoA13*..)
- locked <0x00000000ebaf2830> (a java.lang.Object)
at javax.crypto.KeyGenerator.<init>(DashoA13*..)
at javax.crypto.KeyGenerator.getInstance(DashoA13*..)
at com.sun.net.ssl.internal.ssl.JsseJce.getKeyGenerator(JsseJce.java:223)
at com.sun.net.ssl.internal.ssl.HandshakeMessage$Finished.getFinished(HandshakeMessage.java:1506)
at com.sun.net.ssl.internal.ssl.HandshakeMessage$Finished.<init>(HandshakeMessage.java:1452)
at com.sun.net.ssl.internal.ssl.ServerHandshaker.sendChangeCipherAndFinish(ServerHandshaker.java:1271)
at com.sun.net.ssl.internal.ssl.ServerHandshaker.clientFinished(ServerHandshaker.java:1239)
at com.sun.net.ssl.internal.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:225)
at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:593)
at com.sun.net.ssl.internal.ssl.Handshaker.process_record(Handshaker.java:529)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:943)
- locked <0x00000000eaae9a20> (a com.sun.net.ssl.internal.ssl.SSLSocketImpl)
- locked <0x00000000eaafff18> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1188)
- locked <0x00000000eaaffee8> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1215)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1199)
at org.apache.tomcat.util.net.jsse.JSSESocketFactory.handshake(JSSESocketFactory.java:187)
at org.apache.tomcat.util.net.JIoEndpoint.setSocketOptions(JIoEndpoint.java:686)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:662)
"http-8443-144" daemon prio=10 tid=0x00002aaab83ff000 nid=0x560e waiting for monitor entry [0x00000000581de000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.security.Provider.getService(Provider.java:663)
- waiting to lock <0x00000000a8092130> (a sun.security.provider.Sun)
at sun.security.jca.ProviderList.getService(ProviderList.java:314)
at sun.security.jca.GetInstance.getInstance(GetInstance.java:140)
at java.security.Security.getImpl(Security.java:659)
at java.security.MessageDigest.getInstance(MessageDigest.java:129)
at com.sun.crypto.provider.TlsPrfGenerator.doPRF(DashoA13*..)
at com.sun.crypto.provider.TlsPrfGenerator.engineGenerateKey(DashoA13*..)
at javax.crypto.KeyGenerator.generateKey(DashoA13*..)
at com.sun.net.ssl.internal.ssl.HandshakeMessage$Finished.getFinished(HandshakeMessage.java:1508)
at com.sun.net.ssl.internal.ssl.HandshakeMessage$Finished.verify(HandshakeMessage.java:1474)
at com.sun.net.ssl.internal.ssl.ServerHandshaker.clientFinished(ServerHandshaker.java:1216)
at com.sun.net.ssl.internal.ssl.ServerHandshaker.processMessage(ServerHandshaker.java:225)
at com.sun.net.ssl.internal.ssl.Handshaker.processLoop(Handshaker.java:593)
at com.sun.net.ssl.internal.ssl.Handshaker.process_record(Handshaker.java:529)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:943)
- locked <0x00000000a50d5818> (a com.sun.net.ssl.internal.ssl.SSLSocketImpl)
- locked <0x00000000a50d59e8> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1188)
- locked <0x00000000a50d59a8> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1215)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1199)
at org.apache.tomcat.util.net.jsse.JSSESocketFactory.handshake(JSSESocketFactory.java:187)
at org.apache.tomcat.util.net.JIoEndpoint.setSocketOptions(JIoEndpoint.java:686)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:662)
"http-8443-138" daemon prio=10 tid=0x00002aaab94d6000 nid=0x5608 waiting for monitor entry [0x0000000057bd8000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.security.Provider.getService(Provider.java:663)
- waiting to lock <0x00000000a8092130> (a sun.security.provider.Sun)
at sun.security.jca.ProviderList$ServiceList.tryGet(ProviderList.java:426)
at sun.security.jca.ProviderList$ServiceList.access$200(ProviderList.java:358)
at sun.security.jca.ProviderList$ServiceList$1.hasNext(ProviderList.java:468)
at javax.crypto.Cipher.getInstance(DashoA13*..)
at <blind code>
at <blind code>
at <blind code>
at <blind code>
at <blind code>
at <blind code>
at <blind code>
at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.web.bind.annotation.support.HandlerMethodInvoker.invokeHandlerMethod(HandlerMethodInvoker.java:176)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.invokeHandlerMethod(AnnotationMethodHandlerAdapter.java:426)
at org.springframework.web.servlet.mvc.annotation.AnnotationMethodHandlerAdapter.handle(AnnotationMethodHandlerAdapter.java:414)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:790)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:719)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:644)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:560)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:637)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:717)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:233)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:615)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:861)
at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:606)
at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:489)
at java.lang.Thread.run(Thread.java:662)
전체 ThreadDump 다운로드
상황을 보면 java.security.Provider.getService 부분에서 Lock을 걸고 있어서 다른 Thread 에서 모두 Block 상태가 되어버렸다.
구글링을 해보니 다음과 같이 버그이슈가 등록된 부분이 있다.
http://bugs.java.com/bugdatabase/view_bug.do?bug_id=7092821
아직 해결이 안된 상태이다보니 synchronized 로 인해 bottleneck 이 발생할 수 있는데 딱히 다른 방법은 없는 듯 하다.
다만 평소에는 이상이 없을 정도로 JAVA(tomcat) 가 빠르지만 위의 상태에서는 JAVA가 느려지다보니 위와같이 Block 된 Thread 가 많아지지 않았을까 생각해본다.
(아마 Full GC 가 발생하지 않았을까 추측해 보는데 GC를 남기게 옵션이 설정되어 있지 않아서 정확한 확인이 어렵다. 조만간 GC를 남길 수 있게 옵션을 변경 할 예정..)
추후 동일한 증상의 ThreadDump 발생 시 내용을 업데이트 해야겠다.
댓글
댓글 쓰기