Details

    • Similar Issues:

      Description

      When running on Java 7, Jenkins should ensure that all its ClassLoader instances are marked parallel-capable. This would improve class loading speed in some circumstances—mainly during startup or when first using new features, but also when searching for Groovy imports and the like.

      At least UberClassLoader, DependencyClassLoader, AntClassLoader2, and PluginFirstClassLoader should be so marked. (PluginFirstClassLoader ought to be made to extend AntClassLoader2 since we control it; all superclasses must be marked.) To work on Java 7, can use this idiom:

      try {
          Method m = ClassLoader.class.getDeclaredMethod("registerAsParallelCapable");
          m.setAccessible(true);
          boolean b = (Boolean) m.invoke(null);
          if (!b) {
              ...warn...
          }
      } catch (NoSuchMethodException x) {
          // fine, Java 6
      } catch (Exception x) {
          ...warn...
      }
      

      (Unfortunately this pattern must be repeated in such class, since registerAsParallelCapable is caller-sensitive.)

        Attachments

          Issue Links

            Activity

            jglick Jesse Glick created issue -
            jglick Jesse Glick made changes -
            Field Original Value New Value
            Link This issue is related to JENKINS-24309 [ JENKINS-24309 ]
            rtyler R. Tyler Croy made changes -
            Workflow JNJira [ 156574 ] JNJira + In-Review [ 179333 ]
            Hide
            jglick Jesse Glick added a comment -

            Easier now that core depends on Java 7 anyway.

            Show
            jglick Jesse Glick added a comment - Easier now that core depends on Java 7 anyway.
            jglick Jesse Glick made changes -
            Attachment config.xml [ 33593 ]
            Hide
            jglick Jesse Glick added a comment -

            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 X000X099. (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 …
            
            Show
            jglick Jesse Glick added a comment - 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 …
            jglick Jesse Glick made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            jglick Jesse Glick made changes -
            Assignee Jesse Glick [ jglick ]
            Hide
            jglick Jesse Glick added a comment -

            Ironically, as of JENKINS-24309 we are caching negative results, which would probably include things like X075Customizer that every build of a given job would try to load—but we cannot get to the UberClassLoader.findClass implementation which does this until we acquire the global lock!

            Show
            jglick Jesse Glick added a comment - Ironically, as of JENKINS-24309 we are caching negative results, which would probably include things like X075Customizer that every build of a given job would try to load—but we cannot get to the UberClassLoader.findClass implementation which does this until we acquire the global lock!
            jglick Jesse Glick made changes -
            Labels classloader performance threads classloader performance threads workflow
            Hide
            jglick Jesse Glick added a comment -

            If I set up caching in SandboxResolvingClassLoader, I no longer get contention on UberClassLoader. But the heap still grows to multiple Gbs, and almost every build eventually freezes in

            "Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1958:class-loading-JENKINS-23784 #1958]]" #640 daemon prio=5 os_prio=0 tid=0x00007f1874080000 nid=0x38e9 waiting for monitor entry [0x00007f1800fec000]
               java.lang.Thread.State: BLOCKED (on object monitor)
            	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 java.security.AccessController.doPrivileged(Native Method)
            	at groovy.lang.MetaClassImpl.addProperties(MetaClassImpl.java:2954)
            	at groovy.lang.MetaClassImpl.initialize(MetaClassImpl.java:2937)
            	- locked <0x000000077d266388> (a groovy.lang.MetaClassImpl)
            	at org.codehaus.groovy.reflection.ClassInfo.getMetaClassUnderLock(ClassInfo.java:166)
            	at …
            

            which seems to bypass the cache—whether because it is using the Thread.getContextClassLoader, which would be from Jetty, or because of some other unidentified native lock. An unblocked build looks like

            "Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1990:class-loading-JENKINS-23784 #1990]]" #776 daemon prio=5 os_prio=0 tid=0x00007f1868032000 nid=0x3975 runnable [0x00007f1891605000]
               java.lang.Thread.State: RUNNABLE
            	at java.util.zip.ZipFile.getEntry(Native Method)
            	at java.util.zip.ZipFile.getEntry(ZipFile.java:310)
            	- locked <0x00000006c915ced0> (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 <0x00000006c8ca63c0> (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 com.sun.beans.finder.InstanceFinder.instantiate(InstanceFinder.java:93)
            	at com.sun.beans.finder.InstanceFinder.find(InstanceFinder.java:66)
            	at …
            
            Show
            jglick Jesse Glick added a comment - If I set up caching in SandboxResolvingClassLoader , I no longer get contention on UberClassLoader . But the heap still grows to multiple Gbs, and almost every build eventually freezes in "Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1958:class-loading-JENKINS-23784 #1958]]" #640 daemon prio=5 os_prio=0 tid=0x00007f1874080000 nid=0x38e9 waiting for monitor entry [0x00007f1800fec000] java.lang.Thread.State: BLOCKED (on object monitor) 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 java.security.AccessController.doPrivileged(Native Method) at groovy.lang.MetaClassImpl.addProperties(MetaClassImpl.java:2954) at groovy.lang.MetaClassImpl.initialize(MetaClassImpl.java:2937) - locked <0x000000077d266388> (a groovy.lang.MetaClassImpl) at org.codehaus.groovy.reflection.ClassInfo.getMetaClassUnderLock(ClassInfo.java:166) at … which seems to bypass the cache—whether because it is using the Thread.getContextClassLoader , which would be from Jetty, or because of some other unidentified native lock. An unblocked build looks like "Running CpsFlowExecution[Owner[class-loading-JENKINS-23784/1990:class-loading-JENKINS-23784 #1990]]" #776 daemon prio=5 os_prio=0 tid=0x00007f1868032000 nid=0x3975 runnable [0x00007f1891605000] java.lang.Thread.State: RUNNABLE at java.util.zip.ZipFile.getEntry(Native Method) at java.util.zip.ZipFile.getEntry(ZipFile.java:310) - locked <0x00000006c915ced0> (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 <0x00000006c8ca63c0> (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 com.sun.beans.finder.InstanceFinder.instantiate(InstanceFinder.java:93) at com.sun.beans.finder.InstanceFinder.find(InstanceFinder.java:66) at …
            Hide
            jglick Jesse Glick added a comment -

            I can make CpsVmExecutorService set a more appropriate context loader, which perhaps helps unblock some of these, but others are apparently initiated on the application class loader and so still block. (This is not Jenkins code, so making Jenkins plugin class loaders parallel-capable would not help.)

            Regardless, after a while the system becomes slower and slower and memory usage grows to extreme levels (for example, over 3m instances of java.lang.reflect.Method such as X058.super$1$notify, consuming 268Mb excluding retained objects, after running a few hundred builds). Even after stopping all builds and letting the system go idle, manual GC does not help much. Unfortunately I have not had any success identifying root references.

            Show
            jglick Jesse Glick added a comment - I can make CpsVmExecutorService set a more appropriate context loader, which perhaps helps unblock some of these, but others are apparently initiated on the application class loader and so still block. (This is not Jenkins code, so making Jenkins plugin class loaders parallel-capable would not help.) Regardless, after a while the system becomes slower and slower and memory usage grows to extreme levels (for example, over 3m instances of java.lang.reflect.Method such as X058.super$1$notify , consuming 268Mb excluding retained objects, after running a few hundred builds). Even after stopping all builds and letting the system go idle, manual GC does not help much. Unfortunately I have not had any success identifying root references.
            Hide
            jglick Jesse Glick added a comment -

            I suspect ClassInfo.globalClassSet is failing to relinquish metadata after builds. If true, it is possible Jenkins 2 (which uses Groovy 2) behaves better—need to check.

            Show
            jglick Jesse Glick added a comment - I suspect ClassInfo.globalClassSet is failing to relinquish metadata after builds. If true, it is possible Jenkins 2 (which uses Groovy 2) behaves better—need to check.
            Hide
            jglick Jesse Glick added a comment -

            Filed workflow-cps PR 41 to deal with some memory leak issues I could reproduce in tests—but not this one, which analysis tools still fail to diagnose: the only references seem to be from Introspector.declaredMethodCache, which uses weak references and so should be quickly cleared during normal GC cycles, to say nothing of repeated forced GC.

            These are side issues—not part of the issue reported here, which is lock contention—but the slowdown (whether due to the memory leak or something else) makes it harder to verify that a workaround of this issue is actually effective.

            Show
            jglick Jesse Glick added a comment - Filed workflow-cps PR 41 to deal with some memory leak issues I could reproduce in tests—but not this one, which analysis tools still fail to diagnose: the only references seem to be from Introspector.declaredMethodCache , which uses weak references and so should be quickly cleared during normal GC cycles, to say nothing of repeated forced GC. These are side issues—not part of the issue reported here, which is lock contention—but the slowdown (whether due to the memory leak or something else) makes it harder to verify that a workaround of this issue is actually effective.
            Hide
            jglick Jesse Glick added a comment -

            Indeed, after stopping new builds, while Introspector.flushCaches() had little effect, I managed to get heap to drop from over 3Gb to around 110Mb, by running in /script

            int x = 1024;
            xs = []
            while (true) {
              xs += new Object[x]
              x *= 1.3
            }
            

            until I got an OutOfMemoryError, and then forcing another GC. So this is a SoftReference collection issue. IIRC Groovy 2 eschews the soft references, so Jenkins 2 may scale better after PR 41 is merged. (Not testing that now since I have an independent patch to the same plugin associated with this actual issue.)

            Show
            jglick Jesse Glick added a comment - Indeed, after stopping new builds, while Introspector.flushCaches() had little effect, I managed to get heap to drop from over 3Gb to around 110Mb, by running in /script int x = 1024; xs = [] while ( true ) { xs += new Object [x] x *= 1.3 } until I got an OutOfMemoryError , and then forcing another GC. So this is a SoftReference collection issue. IIRC Groovy 2 eschews the soft references, so Jenkins 2 may scale better after PR 41 is merged. (Not testing that now since I have an independent patch to the same plugin associated with this actual issue.)
            jglick Jesse Glick made changes -
            Remote Link This issue links to "script-security PR 80 (Web Link)" [ 14721 ]
            jglick Jesse Glick made changes -
            Remote Link This issue links to "workflow-cps PR 42 (Web Link)" [ 14722 ]
            jglick Jesse Glick made changes -
            Status In Progress [ 3 ] Open [ 1 ]
            abayer Andrew Bayer made changes -
            Labels classloader performance threads workflow classloader performance pipeline threads workflow
            abayer Andrew Bayer made changes -
            Labels classloader performance pipeline threads workflow classloader performance pipeline threads
            Hide
            jglick Jesse Glick added a comment -

            A related issue I just found while looking at a thread dump from an unresponsive instance: some threads such as

            at hudson.util.MaskingClassLoader.getResource(MaskingClassLoader.java:80)
            - waiting to lock <…> (a hudson.util.MaskingClassLoader)
            at java.lang.ClassLoader.getResource(ClassLoader.java:1091)
            at jenkins.util.AntClassLoader.getResource(AntClassLoader.java:888)
            at org.kohsuke.stapler.ClassDescriptor$ASM.loadParametersFromAsm(ClassDescriptor.java:258)
            at org.kohsuke.stapler.ClassDescriptor$ASM.access$100(ClassDescriptor.java:212)
            at org.kohsuke.stapler.ClassDescriptor.loadParameterNames(ClassDescriptor.java:145)
            at org.kohsuke.stapler.ClassDescriptor.loadConstructorParamNames(ClassDescriptor.java:179)
            at org.jenkinsci.plugins.workflow.cps.DSL.loadSoleArgumentKey(DSL.java:220)
            at org.jenkinsci.plugins.workflow.cps.DSL.parseArgs(DSL.java:356)
            at org.jenkinsci.plugins.workflow.cps.DSL.invokeStep(DSL.java:152)
            at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:124)
            at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:117)
            at …
            

            or

            at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:70)
            - waiting to lock <…> (a hudson.util.MaskingClassLoader)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
            - locked <…> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
            at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1398)
            at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1075)
            - locked <…> (a hudson.ClassicPluginStrategy$AntClassLoader2)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
            at hudson.util.XStream2$AssociatedConverterImpl.findConverter(XStream2.java:318)
            at hudson.util.XStream2$AssociatedConverterImpl.canConvert(XStream2.java:357)
            at com.thoughtworks.xstream.core.DefaultConverterLookup.lookupConverterForType(DefaultConverterLookup.java:59)
            - locked <…> (a com.thoughtworks.xstream.core.DefaultConverterLookup)
            at com.thoughtworks.xstream.XStream$1.lookupConverterForType(XStream.java:498)
            at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:56)
            at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50)
            at com.thoughtworks.xstream.core.TreeUnmarshaller.start(TreeUnmarshaller.java:134)
            at com.thoughtworks.xstream.core.AbstractTreeMarshallingStrategy.unmarshal(AbstractTreeMarshallingStrategy.java:32)
            at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1189)
            at hudson.util.XStream2.unmarshal(XStream2.java:114)
            at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1173)
            at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1044)
            at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1035)
            at …
            

            were blocked on one thread waiting for a lower-level lock:

            at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:390)
            - waiting to lock <…> (a org.eclipse.jetty.webapp.WebAppClassLoader)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
            - locked <…> (a hudson.util.MaskingClassLoader)
            at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:75)
            - locked <…> (a hudson.util.MaskingClassLoader)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:411)
            - locked <…> (a hudson.ClassicPluginStrategy$DependencyClassLoader)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
            at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1398)
            at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1075)
            - locked <…> (a hudson.ClassicPluginStrategy$AntClassLoader2)
            at java.lang.ClassLoader.loadClass(ClassLoader.java:357)
            at …
            

            It is clearly wrong for MaskingClassLoader to be adding its own synchronization here, especially when the only apparent reason for the synchronized statements in this case was to guard access to some rarely-written lists. I will propose a patch.

            Show
            jglick Jesse Glick added a comment - A related issue I just found while looking at a thread dump from an unresponsive instance: some threads such as at hudson.util.MaskingClassLoader.getResource(MaskingClassLoader.java:80) - waiting to lock <…> (a hudson.util.MaskingClassLoader) at java.lang.ClassLoader.getResource(ClassLoader.java:1091) at jenkins.util.AntClassLoader.getResource(AntClassLoader.java:888) at org.kohsuke.stapler.ClassDescriptor$ASM.loadParametersFromAsm(ClassDescriptor.java:258) at org.kohsuke.stapler.ClassDescriptor$ASM.access$100(ClassDescriptor.java:212) at org.kohsuke.stapler.ClassDescriptor.loadParameterNames(ClassDescriptor.java:145) at org.kohsuke.stapler.ClassDescriptor.loadConstructorParamNames(ClassDescriptor.java:179) at org.jenkinsci.plugins.workflow.cps.DSL.loadSoleArgumentKey(DSL.java:220) at org.jenkinsci.plugins.workflow.cps.DSL.parseArgs(DSL.java:356) at org.jenkinsci.plugins.workflow.cps.DSL.invokeStep(DSL.java:152) at org.jenkinsci.plugins.workflow.cps.DSL.invokeMethod(DSL.java:124) at org.jenkinsci.plugins.workflow.cps.CpsScript.invokeMethod(CpsScript.java:117) at … or at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:70) - waiting to lock <…> (a hudson.util.MaskingClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:411) - locked <…> (a hudson.ClassicPluginStrategy$DependencyClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1398) at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1075) - locked <…> (a hudson.ClassicPluginStrategy$AntClassLoader2) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at hudson.util.XStream2$AssociatedConverterImpl.findConverter(XStream2.java:318) at hudson.util.XStream2$AssociatedConverterImpl.canConvert(XStream2.java:357) at com.thoughtworks.xstream.core.DefaultConverterLookup.lookupConverterForType(DefaultConverterLookup.java:59) - locked <…> (a com.thoughtworks.xstream.core.DefaultConverterLookup) at com.thoughtworks.xstream.XStream$1.lookupConverterForType(XStream.java:498) at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:56) at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) at com.thoughtworks.xstream.core.TreeUnmarshaller.start(TreeUnmarshaller.java:134) at com.thoughtworks.xstream.core.AbstractTreeMarshallingStrategy.unmarshal(AbstractTreeMarshallingStrategy.java:32) at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1189) at hudson.util.XStream2.unmarshal(XStream2.java:114) at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1173) at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1044) at com.thoughtworks.xstream.XStream.fromXML(XStream.java:1035) at … were blocked on one thread waiting for a lower-level lock: at org.eclipse.jetty.webapp.WebAppClassLoader.loadClass(WebAppClassLoader.java:390) - waiting to lock <…> (a org.eclipse.jetty.webapp.WebAppClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:411) - locked <…> (a hudson.util.MaskingClassLoader) at hudson.util.MaskingClassLoader.loadClass(MaskingClassLoader.java:75) - locked <…> (a hudson.util.MaskingClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:411) - locked <…> (a hudson.ClassicPluginStrategy$DependencyClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at jenkins.util.AntClassLoader.findBaseClass(AntClassLoader.java:1398) at jenkins.util.AntClassLoader.loadClass(AntClassLoader.java:1075) - locked <…> (a hudson.ClassicPluginStrategy$AntClassLoader2) at java.lang.ClassLoader.loadClass(ClassLoader.java:357) at … It is clearly wrong for MaskingClassLoader to be adding its own synchronization here, especially when the only apparent reason for the synchronized statements in this case was to guard access to some rarely-written lists. I will propose a patch.
            jglick Jesse Glick made changes -
            Remote Link This issue links to "PR 2581 (Web Link)" [ 14928 ]
            Hide
            jglick Jesse Glick added a comment -

            Unfortunately it seems that Jetty’s WebAppClassLoader does not call ClassLoader.registerAsParallelCapable

            Fixed in bug 464442 and available as of 9.3.0. Currently we bundle 9.2.x.

            Show
            jglick Jesse Glick added a comment - Unfortunately it seems that Jetty’s WebAppClassLoader does not call ClassLoader.registerAsParallelCapable Fixed in bug 464442 and available as of 9.3.0. Currently we bundle 9.2.x .
            Hide
            scm_issue_link SCM/JIRA link daemon added a comment -

            Code changed in jenkins
            User: Jesse Glick
            Path:
            core/src/main/java/hudson/util/MaskingClassLoader.java
            http://jenkins-ci.org/commit/jenkins/a04e2f9836263f7ae5e68617f5bafde18e594446
            Log:
            JENKINS-23784 Avoid acquiring ClassLoader locks. (#2581)

            Show
            scm_issue_link SCM/JIRA link daemon added a comment - Code changed in jenkins User: Jesse Glick Path: core/src/main/java/hudson/util/MaskingClassLoader.java http://jenkins-ci.org/commit/jenkins/a04e2f9836263f7ae5e68617f5bafde18e594446 Log: JENKINS-23784 Avoid acquiring ClassLoader locks. (#2581)
            Hide
            oleg_nenashev Oleg Nenashev added a comment -

            > Fixed in bug 464442 and available as of 9.3.0. Currently we bundle 9.2.x.

            IMHO we should schedule the Jetty upgrade to 9.3.x or 9.4.x as a part of the Java 7 deprecation. The problem is that 9.3.x and 9.2.x are not fully binary compatible IIRC

            Show
            oleg_nenashev Oleg Nenashev added a comment - > Fixed in bug 464442 and available as of 9.3.0. Currently we bundle 9.2.x. IMHO we should schedule the Jetty upgrade to 9.3.x or 9.4.x as a part of the Java 7 deprecation. The problem is that 9.3.x and 9.2.x are not fully binary compatible IIRC
            Hide
            jamesdumay James Dumay added a comment - - edited

            Jesse GlickI saw that there is a bunch of PRs for this ticket that have now been merged. Whats the current status of this ticket?

            Show
            jamesdumay James Dumay added a comment - - edited Jesse Glick I saw that there is a bunch of PRs for this ticket that have now been merged. Whats the current status of this ticket?
            cloudbees CloudBees Inc. made changes -
            Remote Link This issue links to "CloudBees Internal CD-268 (Web Link)" [ 18945 ]
            jglick Jesse Glick made changes -
            Assignee Jesse Glick [ jglick ]
            Hide
            jglick Jesse Glick added a comment -

            James Dumay it is open. I think a fix would be easy enough, though verifying its effectiveness is another matter.

            Show
            jglick Jesse Glick added a comment - James Dumay it is open. I think a fix would be easy enough, though verifying its effectiveness is another matter.

              People

              • Assignee:
                Unassigned
                Reporter:
                jglick Jesse Glick
              • Votes:
                0 Vote for this issue
                Watchers:
                6 Start watching this issue

                Dates

                • Created:
                  Updated: