| Attaching a Pipeline job that appears to reproduce lock contention in 1.625.3. You need to Build with Parameters several times (no need to type in any actual parameter). The parameter is there just to ensure that each build actually schedules a new build, rather than coalescing builds in the queue, so the parallelism in effect is equal to the number of manual builds you triggered. (If you do not want to have to kill Jenkins, it is best to leave the Configure screen open: to stop running stuff, comment out the build line and Apply. Later, uncomment it and Apply to get ready again.) The job tries to do a lot of Groovy class loading, using classes X000…X099. (Originally I tried going up to X999, but this quickly exploded with ArrayIndexOutOfBoundsException and such errors; possibly Groovy bugs, not just a scalability issue.) The first thing to note is that there is a lot of stupid class loading traffic through java.beans.Introspector, which almost always winds up failing (after first acquiring contended locks and calling expensive ClassNotFoundException.fillInStackTrace). Using a version of SandboxResolvingClassLoader patches for diagnostics (I need to put this elsewhere, since this loader only gets called for loads initiated in certain ways):
failed to use classLoader hudson.PluginManager$UberClassLoader from Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/227:class-loading-JENKINS-23784 #227]] to load X016Customizer
java.lang.Exception: Stack trace
at java.lang.Thread.dumpStack(Thread.java:1329)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.loadClass(SandboxResolvingClassLoader.java:30)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:692)
at groovy.lang.GroovyClassLoader$InnerLoader.loadClass(GroovyClassLoader.java:445)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:802)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:790)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:103)
at java.beans.Introspector.findCustomizerClass(Introspector.java:1301)
at java.beans.Introspector.getTargetBeanDescriptor(Introspector.java:1295)
at java.beans.Introspector.getBeanInfo(Introspector.java:425)
at java.beans.Introspector.getBeanInfo(Introspector.java:173)
at groovy.lang.MetaClassImpl$15.run(MetaClassImpl.java:2956)
at java.security.AccessController.doPrivileged(Native Method)
at groovy.lang.MetaClassImpl.addProperties(MetaClassImpl.java:2954)
at groovy.lang.MetaClassImpl.initialize(MetaClassImpl.java:2937)
at org.codehaus.groovy.reflection.ClassInfo.getMetaClassUnderLock(ClassInfo.java:166)
at org.codehaus.groovy.reflection.ClassInfo.getMetaClass(ClassInfo.java:182)
at org.codehaus.groovy.runtime.metaclass.MetaClassRegistryImpl.getMetaClass(MetaClassRegistryImpl.java:227)
at org.codehaus.groovy.runtime.InvokerHelper.getMetaClass(InvokerHelper.java:751)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.createCallConstructorSite(CallSiteArray.java:71)
at org.codehaus.groovy.runtime.callsite.CallSiteArray.defaultCallConstructor(CallSiteArray.java:54)
at org.codehaus.groovy.runtime.callsite.AbstractCallSite.callConstructor(AbstractCallSite.java:182)
at org.kohsuke.groovy.sandbox.impl.Checker$3.call(Checker.java:194)
at org.kohsuke.groovy.sandbox.GroovyInterceptor.onNewInstance(GroovyInterceptor.java:40)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxInterceptor.onNewInstance(SandboxInterceptor.java:128)
at org.kohsuke.groovy.sandbox.impl.Checker$3.call(Checker.java:191)
at org.kohsuke.groovy.sandbox.impl.Checker.checkedConstructor(Checker.java:188)
at com.cloudbees.groovy.cps.sandbox.SandboxInvoker.constructorCall(SandboxInvoker.java:19)
at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.dispatchOrArg(FunctionCallBlock.java:93)
at com.cloudbees.groovy.cps.impl.FunctionCallBlock$ContinuationImpl.fixName(FunctionCallBlock.java:74)
at sun.reflect.GeneratedMethodAccessor95.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.cloudbees.groovy.cps.impl.ContinuationPtr$ContinuationImpl.receive(ContinuationPtr.java:72)
at com.cloudbees.groovy.cps.impl.ConstantBlock.eval(ConstantBlock.java:21)
at com.cloudbees.groovy.cps.Next.step(Next.java:58)
at com.cloudbees.groovy.cps.Continuable.run0(Continuable.java:154)
at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.access$001(SandboxContinuable.java:19)
at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:33)
at org.jenkinsci.plugins.workflow.cps.SandboxContinuable$1.call(SandboxContinuable.java:30)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.GroovySandbox.runInSandbox(GroovySandbox.java:108)
at org.jenkinsci.plugins.workflow.cps.SandboxContinuable.run0(SandboxContinuable.java:30)
at org.jenkinsci.plugins.workflow.cps.CpsThread.runNextChunk(CpsThread.java:164)
With a single build running at a time (so no lock contention), every hums along at a decent pace (2–3 builds per second) until around build 1000 or so, at which point it starts taking 10–20s per build. We get a lot of threads doing class loading:
"Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1133:class-loading-JENKINS-23784 #1133]]" #1516 daemon prio=5 os_prio=0 tid=0x00007f0f34131000 nid=0x2345 runnable [0x00007f0eafdfa000]
java.lang.Thread.State: RUNNABLE
at java.lang.ClassLoader.findBootstrapClass(Native Method)
at java.lang.ClassLoader.findBootstrapClassOrNull(ClassLoader.java:1015)
at java.lang.ClassLoader.loadClass(ClassLoader.java:413)
- locked <0x00000006c8935dd8> (a org.jenkinsci.maven.plugins.hpi.JettyAndServletApiOnlyClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:450)
- locked <0x00000006c8935d60> (a org.jenkinsci.maven.plugins.hpi.RunMojo$2)
at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:403)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:67)
at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:110)
at java.beans.Introspector.findCustomizerClass(Introspector.java:1301)
at java.beans.Introspector.getTargetBeanDescriptor(Introspector.java:1295)
at java.beans.Introspector.getBeanInfo(Introspector.java:425)
at java.beans.Introspector.getBeanInfo(Introspector.java:173)
at groovy.lang.MetaClassImpl$15.run(MetaClassImpl.java:2956)
at …as before…
and some apparently parsing:
"Executor #-1 for master : executing class-loading-JENKINS-23784 #1134" #1639 daemon prio=5 os_prio=0 tid=0x00007f0ec40df800 nid=0x2426 runnable [0x00007f0eaac91000]
java.lang.Thread.State: RUNNABLE
at org.codehaus.groovy.control.ResolveVisitor.resolveFromModule(ResolveVisitor.java:537)
at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:268)
at org.codehaus.groovy.control.ResolveVisitor.resolveFromModule(ResolveVisitor.java:578)
at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:268)
at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:236)
at org.codehaus.groovy.control.ResolveVisitor.resolveOrFail(ResolveVisitor.java:220)
at org.codehaus.groovy.control.ResolveVisitor.resolveOrFail(ResolveVisitor.java:232)
at org.codehaus.groovy.control.ResolveVisitor.resolveOrFail(ResolveVisitor.java:228)
at org.codehaus.groovy.control.ResolveVisitor.visitClass(ResolveVisitor.java:1171)
at org.codehaus.groovy.control.ResolveVisitor.startResolving(ResolveVisitor.java:141)
at org.codehaus.groovy.control.CompilationUnit$9.call(CompilationUnit.java:608)
at org.codehaus.groovy.control.CompilationUnit.applyToSourceUnits(CompilationUnit.java:846)
at org.codehaus.groovy.control.CompilationUnit.doPhaseOperation(CompilationUnit.java:550)
at org.codehaus.groovy.control.CompilationUnit.compile(CompilationUnit.java:499)
at groovy.lang.GroovyClassLoader.doParseClass(GroovyClassLoader.java:302)
at groovy.lang.GroovyClassLoader.parseClass(GroovyClassLoader.java:281)
- locked <0x00000007a09fe148> (a java.util.HashMap)
at groovy.lang.GroovyShell.parseClass(GroovyShell.java:731)
at groovy.lang.GroovyShell.parse(GroovyShell.java:743)
at org.jenkinsci.plugins.workflow.cps.CpsGroovyShell.reparse(CpsGroovyShell.java:106)
at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.parseScript(CpsFlowExecution.java:376)
at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.start(CpsFlowExecution.java:343)
at org.jenkinsci.plugins.workflow.job.WorkflowRun.run(WorkflowRun.java:212)
or class loading while parsing:
"Executor #-1 for master : executing class-loading-JENKINS-23784 #1132 loading com.cloudbees.groovy.cps.org.jenkinsci$plugins$workflow$cps$CpsScript" #1633 daemon prio=5 os_prio=0 tid=0x00007f0f4a6f3800 nid=0x241f runnable [0x00007f0eaac91000]
java.lang.Thread.State: RUNNABLE
at java.lang.ClassLoader.findBootstrapClass(Native Method)
at java.lang.ClassLoader.findBootstrapClassOrNull(ClassLoader.java:1015)
at java.lang.ClassLoader.loadClass(ClassLoader.java:413)
- locked <0x00000006c8935dd8> (a org.jenkinsci.maven.plugins.hpi.JettyAndServletApiOnlyClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:450)
- locked <0x00000006c8935d60> (a org.jenkinsci.maven.plugins.hpi.RunMojo$2)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x00000006c8984490> (a hudson.PluginManager$UberClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x000000078484ca10> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.loadClass(SandboxResolvingClassLoader.java:27)
- locked <0x000000078484ca10> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x00000007848538e0> (a groovy.lang.GroovyClassLoader)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:692)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:560)
at org.codehaus.groovy.control.ClassNodeResolver.tryAsLoaderClassOrScript(ClassNodeResolver.java:183)
at org.codehaus.groovy.control.ClassNodeResolver.findClassNode(ClassNodeResolver.java:168)
at org.codehaus.groovy.control.ClassNodeResolver.resolveName(ClassNodeResolver.java:124)
at org.codehaus.groovy.control.ResolveVisitor.resolveToOuter(ResolveVisitor.java:616)
at org.codehaus.groovy.control.ResolveVisitor.resolve(ResolveVisitor.java:268)
at …
(Here I am using mvn hpi:run so the bottom loader is from Jetty. Unfortunately it seems that Jetty’s WebAppClassLoader does not call ClassLoader.registerAsParallelCapable, so until that is fixed, there is no hope of parallelizing loads of classes from Jenkins core.) It is not obvious from the thread dumps why Jenkins slows down, but I think it is due to a memory leak—the heap seems to grow to several Gbs without effective collection. Probably an independent Groovy problem. I did capture a heap dump which showed tens of thousands of Object[] as well as some char[] but unfortunately lost the dump before I could dig deeper. Once you start running a few builds simultaneously, then you see contention:
"Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1603:class-loading-JENKINS-23784 #1603]] loading X075Customizer" #546 daemon prio=5 os_prio=0 tid=0x00007f339c35e000 nid=0x2eb1 waiting for monitor entry [0x00007f33b08b9000]
java.lang.Thread.State: BLOCKED (on object monitor)
at java.lang.ClassLoader.loadClass(ClassLoader.java:404)
- waiting to lock <0x00000006c8cd6658> (a hudson.PluginManager$UberClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x0000000770688fb0> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.loadClass(SandboxResolvingClassLoader.java:28)
- locked <0x0000000770688fb0> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x000000077068f7c0> (a groovy.lang.GroovyClassLoader)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:692)
at groovy.lang.GroovyClassLoader$InnerLoader.loadClass(GroovyClassLoader.java:445)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:802)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:790)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:103)
at java.beans.Introspector.findCustomizerClass(Introspector.java:1301)
at java.beans.Introspector.getTargetBeanDescriptor(Introspector.java:1295)
at java.beans.Introspector.getBeanInfo(Introspector.java:425)
at java.beans.Introspector.getBeanInfo(Introspector.java:173)
at groovy.lang.MetaClassImpl$15.run(MetaClassImpl.java:2956)
at java.security.AccessController.doPrivileged(Native Method)
at groovy.lang.MetaClassImpl.addProperties(MetaClassImpl.java:2954)
at groovy.lang.MetaClassImpl.initialize(MetaClassImpl.java:2937)
- locked <0x00000007765e71d0> (a groovy.lang.MetaClassImpl)
at org.codehaus.groovy.reflection.ClassInfo.getMetaClassUnderLock(ClassInfo.java:166)
at …
"Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1601:class-loading-JENKINS-23784 #1601]] loading X082BeanInfo" #984 daemon prio=5 os_prio=0 tid=0x00007f33cc084000 nid=0x308e runnable [0x00007f338a2f0000]
java.lang.Thread.State: RUNNABLE
at java.util.zip.ZipFile.getEntry(Native Method)
at java.util.zip.ZipFile.getEntry(ZipFile.java:310)
- locked <0x00000006c91cce28> (a java.util.jar.JarFile)
at java.util.jar.JarFile.getEntry(JarFile.java:240)
at java.util.jar.JarFile.getJarEntry(JarFile.java:223)
at sun.misc.URLClassPath$JarLoader.getResource(URLClassPath.java:1005)
at sun.misc.URLClassPath.getResource(URLClassPath.java:212)
at java.net.URLClassLoader$1.run(URLClassLoader.java:365)
at java.net.URLClassLoader$1.run(URLClassLoader.java:362)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:361)
at org.eclipse.jetty.webapp.WebAppClassLoader.findClass(WebAppClassLoader.java:510)
at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:441)
- locked <0x00000006c8c7d448> (a org.jenkinsci.maven.plugins.hpi.RunMojo$2)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x00000006c8cd6658> (a hudson.PluginManager$UberClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x000000076f811d70> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader.loadClass(SandboxResolvingClassLoader.java:28)
- locked <0x000000076f811d70> (a org.jenkinsci.plugins.scriptsecurity.sandbox.groovy.SandboxResolvingClassLoader)
at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
- locked <0x000000076f818580> (a groovy.lang.GroovyClassLoader)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:692)
at groovy.lang.GroovyClassLoader$InnerLoader.loadClass(GroovyClassLoader.java:445)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:802)
at groovy.lang.GroovyClassLoader.loadClass(GroovyClassLoader.java:790)
at java.lang.Class.forName0(Native Method)
at java.lang.Class.forName(Class.java:348)
at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:103)
at com.sun.beans.finder.InstanceFinder.instantiate(InstanceFinder.java:93)
at com.sun.beans.finder.InstanceFinder.find(InstanceFinder.java:66)
at java.beans.Introspector.findExplicitBeanInfo(Introspector.java:448)
at java.beans.Introspector.<init>(Introspector.java:398)
at java.beans.Introspector.getBeanInfo(Introspector.java:173)
at groovy.lang.MetaClassImpl$15.run(MetaClassImpl.java:2956)
at java.security.AccessController.doPrivileged(Native Method)
at groovy.lang.MetaClassImpl.addProperties(MetaClassImpl.java:2954)
at groovy.lang.MetaClassImpl.initialize(MetaClassImpl.java:2937)
- locked <0x0000000776615d60> (a groovy.lang.MetaClassImpl)
at org.codehaus.groovy.reflection.ClassInfo.getMetaClassUnderLock(ClassInfo.java:166)
at …
|
