-
Bug
-
Resolution: Fixed
-
Major
-
Jenkins 1.509.1
Also happened on 1.480.3
Jenkins 1.532
Jenkins takes up to 45 minutes to startup and shows up:
Please wait while Jenkins is getting ready to work
My setup has a thousand jobs, some of them having each a thousands more entries in their build history.
Using strace, I can confirm there is a few threads that are browsing the build history and opening build.xml files. Since we have a ton of them, that takes a very long time.
Attached is a JStack of the process. Thread 19970 was one of them confirmed to load build.xml in strace. The stack trace mentions jenkins.model.lazy.AbstractLazyLoadRunMap but then hudson.model.Run.reload() which in turns make it load all the build.xml files
I have noticed https://issues.jenkins-ci.org/browse/JENKINS-8754 that is about making Jenkins faster to start by using lazy loading of the jobs. That does not seems to lazy load them.
My downstream bug report is https://bugzilla.wikimedia.org/show_bug.cgi?id=47120
- is duplicated by
-
JENKINS-20890 Saving jobs with huge build history takes a very long time due to unnecessary logging
-
- Resolved
-
[JENKINS-17837] slow startup and rename caused by loading all build.xml history
I can confirm that this same issue occurs during a job rename: The entire build history is loaded.
Here is the backtrace:
Handling POST /job/qa-tools-sauce-labs-ui-test-support-java-windows-platforms/doRename : RequestHandlerThread[#11333] java.io.FileInputStream.readBytes(Native Method) java.io.FileInputStream.read(FileInputStream.java:242) java.io.BufferedInputStream.read1(BufferedInputStream.java:273) java.io.BufferedInputStream.read(BufferedInputStream.java:334) java.io.FilterInputStream.read(FilterInputStream.java:133) java.io.PushbackInputStream.read(PushbackInputStream.java:186) sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:283) sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:325) sun.nio.cs.StreamDecoder.read(StreamDecoder.java:177) java.io.InputStreamReader.read(InputStreamReader.java:184) com.thoughtworks.xstream.core.util.XmlHeaderAwareReader.read(XmlHeaderAwareReader.java:223) org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2992) org.xmlpull.mxp1.MXParser.more(MXParser.java:3046) org.xmlpull.mxp1.MXParser.parseEntityRef(MXParser.java:2217) org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1275) org.xmlpull.mxp1.MXParser.next(MXParser.java:1093) com.thoughtworks.xstream.io.xml.XppReader.pullNextEvent(XppReader.java:109) com.thoughtworks.xstream.io.xml.AbstractPullReader.readRealEvent(AbstractPullReader.java:148) com.thoughtworks.xstream.io.xml.AbstractPullReader.readEvent(AbstractPullReader.java:135) com.thoughtworks.xstream.io.xml.AbstractPullReader.getValue(AbstractPullReader.java:180) com.thoughtworks.xstream.io.ReaderWrapper.getValue(ReaderWrapper.java:48) com.thoughtworks.xstream.converters.SingleValueConverterWrapper.unmarshal(SingleValueConverterWrapper.java:49) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) hudson.util.RobustReflectionConverter.unmarshalField(RobustReflectionConverter.java:333) hudson.util.RobustReflectionConverter.doUnmarshal(RobustReflectionConverter.java:275) hudson.util.RobustReflectionConverter.unmarshal(RobustReflectionConverter.java:222) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) com.thoughtworks.xstream.converters.collections.AbstractCollectionConverter.readItem(AbstractCollectionConverter.java:71) hudson.util.RobustCollectionConverter.populateCollection(RobustCollectionConverter.java:85) com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:61) hudson.util.RobustCollectionConverter.unmarshal(RobustCollectionConverter.java:76) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) hudson.util.RobustReflectionConverter.unmarshalField(RobustReflectionConverter.java:333) hudson.util.RobustReflectionConverter.doUnmarshal(RobustReflectionConverter.java:275) hudson.util.RobustReflectionConverter.unmarshal(RobustReflectionConverter.java:222) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) hudson.util.RobustReflectionConverter.unmarshalField(RobustReflectionConverter.java:333) hudson.util.RobustReflectionConverter.doUnmarshal(RobustReflectionConverter.java:275) hudson.util.RobustReflectionConverter.unmarshal(RobustReflectionConverter.java:222) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) com.thoughtworks.xstream.converters.collections.AbstractCollectionConverter.readItem(AbstractCollectionConverter.java:71) hudson.util.RobustCollectionConverter.populateCollection(RobustCollectionConverter.java:85) com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:61) hudson.util.RobustCollectionConverter.unmarshal(RobustCollectionConverter.java:76) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) hudson.util.RobustReflectionConverter.unmarshalField(RobustReflectionConverter.java:333) hudson.util.RobustReflectionConverter.doUnmarshal(RobustReflectionConverter.java:275) hudson.util.RobustReflectionConverter.unmarshal(RobustReflectionConverter.java:222) com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72) com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66) com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50) com.thoughtworks.xstream.core.TreeUnmarshaller.start(TreeUnmarshaller.java:134) com.thoughtworks.xstream.core.AbstractTreeMarshallingStrategy.unmarshal(AbstractTreeMarshallingStrategy.java:32) com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1061) hudson.util.XStream2.unmarshal(XStream2.java:109) com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1045) hudson.XmlFile.unmarshal(XmlFile.java:166) hudson.model.Run.reload(Run.java:311) hudson.model.Run.<init>(Run.java:300) hudson.model.AbstractBuild.<init>(AbstractBuild.java:182) hudson.model.Build.<init>(Build.java:103) hudson.model.FreeStyleBuild.<init>(FreeStyleBuild.java:41) sun.reflect.GeneratedConstructorAccessor65.newInstance(Unknown Source) sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) java.lang.reflect.Constructor.newInstance(Constructor.java:525) hudson.model.AbstractProject.loadBuild(AbstractProject.java:1152) hudson.model.AbstractProject$1.create(AbstractProject.java:339) hudson.model.AbstractProject$1.create(AbstractProject.java:337) hudson.model.RunMap.retrieve(RunMap.java:225) hudson.model.RunMap.retrieve(RunMap.java:59) jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:670) jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:653) jenkins.model.lazy.AbstractLazyLoadRunMap.getById(AbstractLazyLoadRunMap.java:525) jenkins.model.lazy.BuildReferenceMapAdapter.unwrap(BuildReferenceMapAdapter.java:42) jenkins.model.lazy.BuildReferenceMapAdapter.access$200(BuildReferenceMapAdapter.java:27) jenkins.model.lazy.BuildReferenceMapAdapter$SetAdapter._unwrap(BuildReferenceMapAdapter.java:356) jenkins.model.lazy.BuildReferenceMapAdapter$SetAdapter.access$400(BuildReferenceMapAdapter.java:248) jenkins.model.lazy.BuildReferenceMapAdapter$SetAdapter$1.adapt(BuildReferenceMapAdapter.java:271) jenkins.model.lazy.BuildReferenceMapAdapter$SetAdapter$1.adapt(BuildReferenceMapAdapter.java:269) hudson.util.AdaptedIterator.next(AdaptedIterator.java:54) com.google.common.collect.Iterators$7.computeNext(Iterators.java:648) com.google.common.collect.AbstractIterator.tryToComputeNext(AbstractIterator.java:143) com.google.common.collect.AbstractIterator.hasNext(AbstractIterator.java:138) java.util.Collections$UnmodifiableCollection$1.hasNext(Collections.java:1066) java.util.AbstractMap$2$1.hasNext(AbstractMap.java:381) org.jvnet.hudson.plugins.DownStreamProjectActionFactory.createFor(DownStreamProjectActionFactory.java:59) hudson.model.AbstractProject.createTransientActions(AbstractProject.java:756) hudson.model.Project.createTransientActions(Project.java:213) hudson.model.AbstractProject.updateTransientActions(AbstractProject.java:746) hudson.model.AbstractProject.save(AbstractProject.java:284) hudson.plugins.copyartifact.CopyArtifact$ListenerImpl.onRenamed(CopyArtifact.java:331) hudson.model.AbstractItem.renameTo(AbstractItem.java:295) hudson.model.Job.renameTo(Job.java:608) hudson.model.Job.doDoRename(Job.java:1371) sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) java.lang.reflect.Method.invoke(Method.java:601) org.kohsuke.stapler.Function$InstanceFunction.invoke(Function.java:297) org.kohsuke.stapler.interceptor.RequirePOST$Processor.invoke(RequirePOST.java:46) org.kohsuke.stapler.Function$InterceptedFunction.invoke(Function.java:398) org.kohsuke.stapler.Function.bindAndInvoke(Function.java:160) org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:95) org.kohsuke.stapler.MetaClass$1.doDispatch(MetaClass.java:111) org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53) org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:685) org.kohsuke.stapler.Stapler.invoke(Stapler.java:799) org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:239) org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53) org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:685) org.kohsuke.stapler.Stapler.invoke(Stapler.java:799) org.kohsuke.stapler.Stapler.invoke(Stapler.java:587) org.kohsuke.stapler.Stapler.service(Stapler.java:218) javax.servlet.http.HttpServlet.service(HttpServlet.java:45) winstone.ServletConfiguration.execute(ServletConfiguration.java:248) winstone.RequestDispatcher.forward(RequestDispatcher.java:333) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:376) hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:96) net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:208) net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:181) net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:86) org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:84) hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:66) hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:58) hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:99) hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:88) winstone.FilterConfiguration.execute(FilterConfiguration.java:194) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366) hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:48) winstone.FilterConfiguration.execute(FilterConfiguration.java:194) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:84) hudson.security.UnwrapSecurityExceptionFilter.doFilter(UnwrapSecurityExceptionFilter.java:51) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) jenkins.security.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:117) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) org.acegisecurity.providers.anonymous.AnonymousProcessingFilter.doFilter(AnonymousProcessingFilter.java:125) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) org.acegisecurity.ui.rememberme.RememberMeProcessingFilter.doFilter(RememberMeProcessingFilter.java:142) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:271) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) org.acegisecurity.ui.basicauth.BasicProcessingFilter.doFilter(BasicProcessingFilter.java:174) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) jenkins.security.ApiTokenFilter.doFilter(ApiTokenFilter.java:64) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249) hudson.security.HttpSessionContextIntegrationFilter2.doFilter(HttpSessionContextIntegrationFilter2.java:67) hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87) hudson.security.ChainedServletFilter.doFilter(ChainedServletFilter.java:76) hudson.security.HudsonFilter.doFilter(HudsonFilter.java:164) winstone.FilterConfiguration.execute(FilterConfiguration.java:194) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366) org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:46) winstone.FilterConfiguration.execute(FilterConfiguration.java:194) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366) hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81) winstone.FilterConfiguration.execute(FilterConfiguration.java:194) winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366) winstone.RequestDispatcher.forward(RequestDispatcher.java:331) winstone.RequestHandlerThread.processRequest(RequestHandlerThread.java:227) winstone.RequestHandlerThread.run(RequestHandlerThread.java:150) java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) java.util.concurrent.FutureTask.run(FutureTask.java:166) winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77) java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) java.lang.Thread.run(Thread.java:722)
Once this is done I'll try disabling the plugin.
This also blocks other http requests until completion:
hudson.model.Job.isHoldOffBuildUntilSave(Job.java:258)
Which includes requests to view views.
Disabling the Downstream buildview plugin also resolved this issue for me. Cool!
Code changed in jenkins
User: Jesse Glick
Path:
src/main/java/org/jvnet/hudson/plugins/DownStreamProjectActionFactory.java
http://jenkins-ci.org/commit/downstream-buildview-plugin/47801c278f000b34eae5bd9d674029cf470cd8b2
Log:
[FIXED JENKINS-17837] Deleting DownStreamProjectActionFactory.
It cannot be done efficiently in modern versions of Jenkins.
Anyway it has no clear purpose, since DownstreamBuildViewRunListener already adds the action to each new build.
Its only purpose seems to have been to retroactively modify builds started before this plugin was installed,
which seems both ill-advised and unnecessary.
So looking at the Jstack again, I have noticed one of them was refering a plugin: https://wiki.jenkins-ci.org/display/JENKINS/Downstream+buildview+plugin I have disabled that and now my Jenkins boot instantly.
I guess this bug need to be reassigned to the downstream-buildview plugin.