thread blocked at jdk.internal.loader.URLClassPath.getLoader after use javaagent

[huange7]

When we conducted stress tests on some interfaces, we found that the interface latency would occasionally increase. Finally, it was found that it was blocked at the getLoader method, and this occurred after the introduction of the javaagent. What could be the cause of this?

net.bytebuddy.matcher.ElementMatcher$Junction$Conjunction.matches:146:146 [9570ms]
net.bytebuddy.matcher.ElementMatcher$Junction$Disjunction.matches:214:214 [5024ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.matches:17:17 [5024ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.matches:41:41 [5024ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher$Manager.match:85:85 [5024ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.access$200:17:17 [5024ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.hasResources:51:51 [5024ms]
java.lang.ClassLoader.getResource:1401:1401 [5024ms]
org.apache.catalina.loader.WebappClassLoaderBase.getResource:1048:1048 [5024ms]
java.lang.ClassLoader.getResource:1406:1406 [5024ms]
jdk.internal.loader.BuiltinClassLoader.findResource:302:302 [5024ms]
jdk.internal.loader.BuiltinClassLoader.findResourceOnClassPath:478:478 [5024ms]
jdk.internal.loader.URLClassPath.findResource:291:291 [5024ms]
jdk.internal.loader.URLClassPath.getLoader:423:423 [5024ms]

This will result in high time consumption for some Tomcat threads

[laurit]

I'd guess that your application is creating a new class loader and loading new classes on each request. For every class loader instrumentation tries to figure out which instrumentations could apply. This involves doing resource lookups, which can be expensive. What version of the agent are you using? If it is 2.x have you enabled any of the instrumentations that were disabled by default?

[huange7]

this is a part of the stack:

java.lang.Thread.run:829:829 [3361ms]
org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run:61:61 [3361ms]
java.util.concurrent.ThreadPoolExecutor$Worker.run:628:628 [3361ms]
java.util.concurrent.ThreadPoolExecutor.runWorker:1128:1128 [3361ms]
org.apache.tomcat.util.net.SocketProcessorBase.run:49:49 [3361ms]
org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun:1639:1639 [3361ms]
org.apache.coyote.AbstractProtocol$ConnectionHandler.process:868:868 [3361ms]
org.apache.coyote.AbstractProcessorLight.process:65:65 [3361ms]
org.apache.coyote.http11.Http11Processor.service:367:367 [3361ms]
org.apache.catalina.connector.CoyoteAdapter.service:343:343 [3361ms]
org.apache.catalina.valves.RemoteIpValve.invoke:747:747 [3361ms]
org.apache.catalina.core.StandardEngineValve.invoke:74:74 [3361ms]
org.apache.catalina.valves.ErrorReportValve.invoke:92:92 [3361ms]
org.apache.catalina.core.StandardHostValve.invoke:139:139 [3361ms]
org.apache.catalina.authenticator.AuthenticatorBase.invoke:541:541 [3361ms]
org.apache.catalina.core.StandardContextValve.invoke:96:96 [3361ms]
org.apache.catalina.core.StandardWrapperValve.invoke:202:202 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.filter.OncePerRequestFilter.doFilter:119:119 [3361ms]
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal:201:201 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.filter.OncePerRequestFilter.doFilter:119:119 [3361ms]
org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal:109:109 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.servlet.v3_1.OpenTelemetryHandlerMappingFilter.doFilter:73:73 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.filter.OncePerRequestFilter.doFilter:119:119 [3361ms]
org.springframework.web.filter.FormContentFilter.doFilterInternal:93:93 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.filter.OncePerRequestFilter.doFilter:119:119 [3361ms]
org.springframework.web.filter.RequestContextFilter.doFilterInternal:100:100 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.web.filter.DelegatingFilterProxy.doFilter:271:271 [3361ms]
org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate:358:358 [3361ms]
org.springframework.security.web.FilterChainProxy.doFilter:178:178 [3361ms]
org.springframework.security.web.FilterChainProxy.doFilterInternal:209:209 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.security.web.FilterChainProxy.doFilter:186:186 [3361ms]
org.springframework.security.web.FilterChainProxy.doFilterInternal:209:209 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter:90:90 [3361ms]
org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke:126:126 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:193:193 [3361ms]
org.apache.tomcat.websocket.server.WsFilter.doFilter:53:53 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.doFilter:166:166 [3361ms]
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter:231:231 [3361ms]
javax.servlet.http.HttpServlet.service:741:741 [3361ms]
org.springframework.web.servlet.FrameworkServlet.service:883:883 [3361ms]
javax.servlet.http.HttpServlet.service:660:660 [3361ms]
org.springframework.web.servlet.FrameworkServlet.doPost:909:909 [3361ms]
org.springframework.web.servlet.FrameworkServlet.processRequest:1006:1006 [3361ms]
org.springframework.web.servlet.DispatcherServlet.doService:943:943 [3361ms]
org.springframework.web.servlet.DispatcherServlet.doDispatch:1040:1040 [3361ms]
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle:87:87 [3361ms]
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal:793:793 [3361ms]
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod:879:879 [3361ms]
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle:106:106 [3361ms]
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest:138:138 [3361ms]
org.springframework.web.method.support.InvocableHandlerMethod.doInvoke:190:190 [3361ms]
java.lang.reflect.Method.invoke:566:566 [3361ms]
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke:43:43 [3361ms]
jdk.internal.reflect.GeneratedMethodAccessor165.invoke:-1:-1 [3361ms]
com.my.controller.Controller.myMethod:73:73 [3361ms]
com.my.utils.JSONUtils.toTimeCompatibleJSON:44:44 [3361ms]
com.my.utils.JSONUtils.toCompatibleJSON:104:104 [3361ms]
com.alibaba.fastjson.serializer.JSONSerializer.write:285:285 [2433ms]
com.alibaba.fastjson.serializer.MapSerializer.write:44:44 [2433ms]
com.alibaba.fastjson.serializer.MapSerializer.write:271:271 [517ms]
com.alibaba.fastjson.serializer.ListSerializer.write:128:128 [517ms]
com.alibaba.fastjson.serializer.JSONSerializer.getObjectWriter:416:416 [517ms]
com.alibaba.fastjson.serializer.SerializeConfig.getObjectWriter:436:436 [517ms]
com.alibaba.fastjson.serializer.SerializeConfig.getObjectWriter:792:792 [517ms]
com.alibaba.fastjson.serializer.SerializeConfig.createJavaBeanSerializer:120:120 [517ms]
com.alibaba.fastjson.serializer.SerializeConfig.createJavaBeanSerializer:248:248 [517ms]
com.alibaba.fastjson.serializer.SerializeConfig.createASMSerializer:92:92 [517ms]
com.alibaba.fastjson.serializer.ASMSerializerFactory.createJavaBeanSerializer:412:412 [517ms]
com.alibaba.fastjson.util.ASMClassLoader.defineClassPublic:174:174 [517ms]
java.lang.ClassLoader.defineClass:1022:1022 [517ms]
java.lang.ClassLoader.defineClass1:-2:-2 [517ms]
sun.instrument.InstrumentationImpl.transform:563:563 [517ms]
sun.instrument.TransformerManager.transform:188:188 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$ByteBuddy$ModuleSupport.transform:-1:-1 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform:12388:12388 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doPrivileged:-1:-1 [517ms]
java.security.AccessController.doPrivileged:-2:-2 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$Java9CapableVmDispatcher.run:12866:12866 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer$Java9CapableVmDispatcher.run:12936:12936 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.access$1800:12154:12154 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.transform:12445:12445 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$Default$ExecutingTransformer.doTransform:12487:12487 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$RawMatcher$Conjunction.matches:1808:1808 [517ms]
net.bytebuddy.agent.builder.AgentBuilder$RawMatcher$ForElementMatchers.matches:1973:1973 [517ms]
io.opentelemetry.javaagent.tooling.bytebuddy.LoggingFailSafeMatcher.matches:48:48 [517ms]
io.opentelemetry.javaagent.tooling.util.NamedMatcher.matches:26:26 [517ms]
net.bytebuddy.matcher.ElementMatcher$Junction$Conjunction.matches:146:146 [517ms]
net.bytebuddy.matcher.ElementMatcher$Junction$Disjunction.matches:214:214 [220ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.matches:17:17 [220ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.matches:41:41 [220ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher$Manager.match:85:85 [220ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.access$200:17:17 [220ms]
io.opentelemetry.javaagent.extension.matcher.ClassLoaderHasClassesNamedMatcher.hasResources:51:51 [220ms]
java.lang.ClassLoader.getResource:1401:1401 [220ms]
org.apache.catalina.loader.WebappClassLoaderBase.getResource:1048:1048 [220ms]
java.lang.ClassLoader.getResource:1406:1406 [220ms]
jdk.internal.loader.BuiltinClassLoader.findResource:302:302 [220ms]
jdk.internal.loader.BuiltinClassLoader.findResourceOnClassPath:478:478 [220ms]
jdk.internal.loader.URLClassPath.findResource:291:291 [220ms]
jdk.internal.loader.URLClassPath.getLoader:423:423 [220ms]

[laurit]

To me this is strange as usually such classes are generated only once. Are you saying that in you application on every request a new class is generated? Or is the class generated only once and only the first invocation is slow?

[huange7]

Slow calls occur occasionally. They are not slow only for the first request, nor are they slow for every request.

[laurit]

We could ignore com.alibaba.fastjson.util.ASMClassLoader #11954 that should resolve the issue. Though if new instances of ASMClassLoader are being created it could also very well be a bug in your application (are you creating new SerializeConfig instances?) or something completely different.

[huange7]

We could ignore com.alibaba.fastjson.util.ASMClassLoader #11954 that should resolve the issue.

I will try to do so.

are you creating new SerializeConfig instances?

I need to confirm this.

[huange7]

What would happen if this "ignore" were not added? Why might "ignore" solve the problem?

[laurit]

What would happen if this "ignore" were not added? Why might "ignore" solve the problem?

Ignoring class loader disables instrumenting classes loaded by the class loaders with the given name. From the stack trace the problematic bit is checking which instrumentations should run in the class loader ignoring the class loader should help. You could try this out by using the opentelemetry-javaagent.jar from the pull request #11954 (see the artifacts section in https://github.com/open-telemetry/opentelemetry-java-instrumentation/actions/runs/10266201088 for the download link) or build a custom extension (see https://github.com/open-telemetry/opentelemetry-java-instrumentation/blob/main/examples/extension/src/main/java/com/example/javaagent/DemoIgnoredTypesConfigurer.java) Since the class loader contains only generated classes there shouldn't be anything that we need to instrument, so ignoring them should be fine. Let us know whether this helps.
If the issue is really caused by creating a lot of com.alibaba.fastjson.util.ASMClassLoader instances then there probably is another bug in either the framework that generates these or in the way you use it. Imo these serializers should be created only once for each class.

[huange7]

@laurit Thank you for your help! Now the time consumption is relatively normal.