Spring-cloud-sleuth: Performance issue when used with spring-boot-starter-websocket together

Created on 26 Apr 2018 · 2Comments · Source: spring-cloud/spring-cloud-sleuth

Bug report
Spring Boot version: 1.5.12.RELEASE
Spring Cloud version: Edgware.SR2

Description:
We are using spring-boot-starter-websocket to develop websocket application, it's wonderful, but recently when we add spring-cloud-sleuth feature, we found that the throughput is decreasing,
I get a thread dump and found the reason：

jstack1.log

summary is here:
Many thread is in this state (wait for monitor entry [0x00007f29a8da0000]):

"clientInboundChannel-6" #308 prio=5 os_prio=0 tid=0x00007f2a0464a000 nid=0x60d4 waiting for monitor entry [0x00007f29a8da0000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:49)
    - waiting to lock <0x00000000e19c4ba0> (a org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
    at org.springframework.util.ClassUtils.forName(ClassUtils.java:251)
    at org.springframework.util.ClassUtils.isPresent(ClassUtils.java:328)
    at org.springframework.cloud.sleuth.instrument.messaging.AbstractTraceChannelInterceptor.getChannelName(AbstractTraceChannelInterceptor.java:102)
    at org.springframework.cloud.sleuth.instrument.messaging.AbstractTraceChannelInterceptor.getMessageChannelName(AbstractTraceChannelInterceptor.java:119)
    at org.springframework.cloud.sleuth.instrument.messaging.TraceChannelInterceptor.preSend(TraceChannelInterceptor.java:112)
    at org.springframework.messaging.support.AbstractMessageChannel$ChannelInterceptorChain.applyPreSend(AbstractMessageChannel.java:158)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:113)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:104)
    at org.springframework.messaging.simp.SimpMessagingTemplate.sendInternal(SimpMessagingTemplate.java:184)
    at org.springframework.messaging.simp.SimpMessagingTemplate.doSend(SimpMessagingTemplate.java:159)
    at org.springframework.messaging.simp.SimpMessagingTemplate.doSend(SimpMessagingTemplate.java:47)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.send(AbstractMessageSendingTemplate.java:105)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:143)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:123)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:118)
        ......
    org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:180)
    at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:112)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMatch(AbstractMethodMessageHandler.java:504)
    at org.springframework.messaging.simp.annotation.support.SimpAnnotationMethodMessageHandler.handleMatch(SimpAnnotationMethodMessageHandler.java:495)
    at org.springframework.messaging.simp.annotation.support.SimpAnnotationMethodMessageHandler.handleMatch(SimpAnnotationMethodMessageHandler.java:87)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMessageInternal(AbstractMethodMessageHandler.java:463)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMessage(AbstractMethodMessageHandler.java:401)
    at org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask.run(ExecutorSubscribableChannel.java:135)
    at org.springframework.cloud.sleuth.instrument.async.SpanContinuingTraceRunnable.run(SpanContinuingTraceRunnable.java:52)
    ......
    at java.lang.Thread.run(Thread.java:745)

and the lock is holded by this thread:

"clientInboundChannel-5" #307 prio=5 os_prio=0 tid=0x00007f2a04648000 nid=0x60d3 runnable [0x00007f29a8ea1000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.Throwable.fillInStackTrace(Native Method)
    at java.lang.Throwable.fillInStackTrace(Throwable.java:783)
    - locked <0x00000000fd3a9980> (a java.lang.ClassNotFoundException)
    at java.lang.Throwable.<init>(Throwable.java:287)
    at java.lang.Exception.<init>(Exception.java:84)
    at java.lang.ReflectiveOperationException.<init>(ReflectiveOperationException.java:75)
    at java.lang.ClassNotFoundException.<init>(ClassNotFoundException.java:82)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:381)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:424)
    - locked <0x00000000e44a7698> (a java.lang.Object)
    at org.springframework.boot.loader.LaunchedURLClassLoader.loadClass(LaunchedURLClassLoader.java:94)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadFromParent(TomcatEmbeddedWebappClassLoader.java:93)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader.doLoadClass(TomcatEmbeddedWebappClassLoader.java:66)
    at org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:50)
    - locked <0x00000000e19c4ba0> (a org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1119)
    at org.springframework.util.ClassUtils.forName(ClassUtils.java:251)
    at org.springframework.util.ClassUtils.isPresent(ClassUtils.java:328)
    at org.springframework.cloud.sleuth.instrument.messaging.AbstractTraceChannelInterceptor.getChannelName(AbstractTraceChannelInterceptor.java:102)
    at org.springframework.cloud.sleuth.instrument.messaging.AbstractTraceChannelInterceptor.getMessageChannelName(AbstractTraceChannelInterceptor.java:119)
    at org.springframework.cloud.sleuth.instrument.messaging.TraceChannelInterceptor.preSend(TraceChannelInterceptor.java:112)
    at org.springframework.messaging.support.AbstractMessageChannel$ChannelInterceptorChain.applyPreSend(AbstractMessageChannel.java:158)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:113)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:104)
    at org.springframework.messaging.simp.broker.SimpleBrokerMessageHandler.sendMessageToSubscribers(SimpleBrokerMessageHandler.java:348)
    at org.springframework.messaging.simp.broker.SimpleBrokerMessageHandler.handleMessageInternal(SimpleBrokerMessageHandler.java:263)
    at org.springframework.messaging.simp.broker.AbstractBrokerMessageHandler.handleMessage(AbstractBrokerMessageHandler.java:232)
    at org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask.run(ExecutorSubscribableChannel.java:135)
    at org.springframework.messaging.support.ExecutorSubscribableChannel.sendInternal(ExecutorSubscribableChannel.java:91)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:117)
    at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:104)
    at org.springframework.messaging.simp.SimpMessagingTemplate.sendInternal(SimpMessagingTemplate.java:184)
    at org.springframework.messaging.simp.SimpMessagingTemplate.doSend(SimpMessagingTemplate.java:159)
    at org.springframework.messaging.simp.SimpMessagingTemplate.doSend(SimpMessagingTemplate.java:47)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.send(AbstractMessageSendingTemplate.java:105)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:143)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:123)
    at org.springframework.messaging.core.AbstractMessageSendingTemplate.convertAndSend(AbstractMessageSendingTemplate.java:118)
    at cn.com.duiba.millionaire.web.websocket.impl.WsSendMsgTplServiceImpl.sendMsg(WsSendMsgTplServiceImpl.java:37)
    at cn.com.duiba.millionaire.web.websocket.impl.PushQuestionHandleServiceImpl.pushQuestionDetail(PushQuestionHandleServiceImpl.java:55)
    at cn.com.duiba.millionaire.web.websocket.impl.PushMessageHandleServiceImpl.pushQuestionDetail(PushMessageHandleServiceImpl.java:27)
    at cn.com.duiba.millionaire.web.controller.websocket.WebSocketPerfController.pushQuestionDetail(WebSocketPerfController.java:143)
    at sun.reflect.GeneratedMethodAccessor173.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:180)
    at org.springframework.messaging.handler.invocation.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:112)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMatch(AbstractMethodMessageHandler.java:504)
    at org.springframework.messaging.simp.annotation.support.SimpAnnotationMethodMessageHandler.handleMatch(SimpAnnotationMethodMessageHandler.java:495)
    at org.springframework.messaging.simp.annotation.support.SimpAnnotationMethodMessageHandler.handleMatch(SimpAnnotationMethodMessageHandler.java:87)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMessageInternal(AbstractMethodMessageHandler.java:463)
    at org.springframework.messaging.handler.invocation.AbstractMethodMessageHandler.handleMessage(AbstractMethodMessageHandler.java:401)
    at org.springframework.messaging.support.ExecutorSubscribableChannel$SendTask.run(ExecutorSubscribableChannel.java:135)
    at org.springframework.cloud.sleuth.instrument.async.SpanContinuingTraceRunnable.run(SpanContinuingTraceRunnable.java:52)
        ...
    at java.lang.Thread.run(Thread.java:745)

I noticed that every time a message is sent via websocket, It is recorded by sleuth, and the method ClassUtils.isPresent is called, but the result will not be cached, and the method TomcatEmbeddedWebappClassLoader.loadClass is synchronized, so bottleneck is here(I have tested method ClassUtils.isPresent, it will cost 4ms averagely), Maybe you should cache the result of ClassUtils.isPresent at the method caller's side, or remove the synchronized keyword of method TomcatEmbeddedWebappClassLoader.loadClass, and maybe there are more locations where ClassUtils.isPresent will be called frequently which will cause this performance issue.

Looking forward to your reply, thanks.

bug

Source

aftersss

All 2 comments

Thanks for the pointer @aftersss . That was a really good issue description. With this change we're checking if the class is present when the bean is started. Can you check against the latest snapshots that the issue got fixed?