[JENKINS-31791] Cannot load job pages due to HistoryWidget hanging

[timja]

Job pages will not load. Get request never fulfilled. Web browser just idles eventually timing out. ThreadDump reveals it's an issue with HistoryWidget (see below). Reverting back to Jenkins 1.620 fixes problem.

THREAD DUMP:

*Handling GET /job/run_test_whck/ from 10.254.24.129 : RequestHandlerThread[#9] Job/index.jelly AbstractProject/sidepanel.jelly HistoryWidget/index.jelly
*
"Handling GET /job/run_test_whck/ from 10.254.24.129 : RequestHandlerThread[#9] Job/index.jelly AbstractProject/sidepanel.jelly HistoryWidget/index.jelly" Id=95 Group=main RUNNABLE
    at java.io.FileInputStream.available(Native Method)
    at java.io.BufferedInputStream.available(Unknown Source)
    -  locked java.io.BufferedInputStream@1af40c8
    at java.io.FilterInputStream.available(Unknown Source)
    at java.io.PushbackInputStream.available(Unknown Source)
    at sun.nio.cs.StreamDecoder.inReady(Unknown Source)
    at sun.nio.cs.StreamDecoder.implRead(Unknown Source)
    at sun.nio.cs.StreamDecoder.read(Unknown Source)
    -  locked java.io.InputStreamReader@1dbaa6a
    at java.io.InputStreamReader.read(Unknown Source)
    at com.thoughtworks.xstream.core.util.XmlHeaderAwareReader.read(XmlHeaderAwareReader.java:223)
    at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2992)
    at org.xmlpull.mxp1.MXParser.more(MXParser.java:3046)
    at org.xmlpull.mxp1.MXParser.parseStartTag(MXParser.java:1738)
    at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1127)
    at org.xmlpull.mxp1.MXParser.next(MXParser.java:1093)
    at com.thoughtworks.xstream.io.xml.XppReader.pullNextEvent(XppReader.java:109)
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readRealEvent(AbstractPullReader.java:148)
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.readEvent(AbstractPullReader.java:135)
    at com.thoughtworks.xstream.io.xml.AbstractPullReader.hasMoreChildren(AbstractPullReader.java:87)
    at com.thoughtworks.xstream.io.ReaderWrapper.hasMoreChildren(ReaderWrapper.java:32)
    at hudson.util.RobustCollectionConverter.populateCollection(RobustCollectionConverter.java:82)
    at com.thoughtworks.xstream.converters.collections.CollectionConverter.unmarshal(CollectionConverter.java:80)
    at hudson.util.RobustCollectionConverter.unmarshal(RobustCollectionConverter.java:76)
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72)
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65)
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66)
    at hudson.util.RobustReflectionConverter.unmarshalField(RobustReflectionConverter.java:352)
    at hudson.util.RobustReflectionConverter.doUnmarshal(RobustReflectionConverter.java:290)
    at hudson.util.RobustReflectionConverter.unmarshal(RobustReflectionConverter.java:229)
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72)
    at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65)
    at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66)
    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:113)
    at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1173)
    at hudson.XmlFile.unmarshal(XmlFile.java:163)
    at hudson.model.Run.reload(Run.java:326)
    at hudson.model.Run.(Run.java:314)
    at hudson.model.AbstractBuild.(AbstractBuild.java:175)
    at hudson.model.Build.(Build.java:103)
    at hudson.model.FreeStyleBuild.(FreeStyleBuild.java:38)
    at sun.reflect.GeneratedConstructorAccessor104.newInstance(Unknown Source)
    at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(Unknown Source)
    at java.lang.reflect.Constructor.newInstance(Unknown Source)
    at jenkins.model.lazy.LazyBuildMixIn.loadBuild(LazyBuildMixIn.java:156)
    at jenkins.model.lazy.LazyBuildMixIn$1.create(LazyBuildMixIn.java:133)
    at hudson.model.RunMap.retrieve(RunMap.java:223)
    at hudson.model.RunMap.retrieve(RunMap.java:56)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:465)
    -  locked hudson.model.RunMap@91485d
    at jenkins.model.lazy.AbstractLazyLoadRunMap.load(AbstractLazyLoadRunMap.java:448)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.getByNumber(AbstractLazyLoadRunMap.java:356)
    at jenkins.model.lazy.AbstractLazyLoadRunMap.search(AbstractLazyLoadRunMap.java:332)
    at jenkins.model.lazy.LazyBuildMixIn$RunMixIn.getPreviousBuild(LazyBuildMixIn.java:355)
    at hudson.model.AbstractBuild.getPreviousBuild(AbstractBuild.java:196)
    at hudson.model.AbstractBuild.getPreviousBuild(AbstractBuild.java:104)
    at hudson.model.RunMap$1.next(RunMap.java:109)
    at hudson.model.RunMap$1.next(RunMap.java:98)
    at org.apache.commons.collections.IteratorUtils.toList(IteratorUtils.java:849)
    at org.apache.commons.collections.IteratorUtils.toList(IteratorUtils.java:825)
    at hudson.widgets.BuildHistoryWidget.getHistoryPageFilter(BuildHistoryWidget.java:81)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
    at java.lang.reflect.Method.invoke(Unknown Source)
    at org.apache.commons.jexl.util.PropertyExecutor.execute(PropertyExecutor.java:125)
    at org.apache.commons.jexl.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:314)
    at org.apache.commons.jexl.parser.ASTArrayAccess.evaluateExpr(ASTArrayAccess.java:185)
    at org.apache.commons.jexl.parser.ASTIdentifier.execute(ASTIdentifier.java:75)
    at org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
    at org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
    at org.apache.commons.jexl.parser.ASTReferenceExpression.value(ASTReferenceExpression.java:51)
    at org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
    at hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:74)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$3.run(CoreTagLibrary.java:134)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
    at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
    at org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:147)
    at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
    at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
    at org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:150)
    at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
    at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
    at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
    at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
    at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
    at org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:147)
    at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
    at org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
    at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
    at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
    at org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
    at org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
    at org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
    at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63)
    at org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53)
    at org.kohsuke.stapler.jelly.JellyClassTearOff.serveIndexJelly(JellyClassTearOff.java:112)
    at org.kohsuke.stapler.jelly.JellyFacet.handleIndexRequest(JellyFacet.java:127)
    at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:735)
    at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
    at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:249)
    at org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
    at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
    at org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
    at org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
    at org.kohsuke.stapler.Stapler.service(Stapler.java:238)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:686)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1494)
    at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:132)
    at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:123)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
    at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:49)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:84)
    at hudson.security.UnwrapSecurityExceptionFilter.doFilter(UnwrapSecurityExceptionFilter.java:51)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at jenkins.security.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:117)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at org.acegisecurity.providers.anonymous.AnonymousProcessingFilter.doFilter(AnonymousProcessingFilter.java:125)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at org.acegisecurity.ui.rememberme.RememberMeProcessingFilter.doFilter(RememberMeProcessingFilter.java:142)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at org.acegisecurity.ui.AbstractProcessingFilter.doFilter(AbstractProcessingFilter.java:271)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at jenkins.security.BasicHeaderProcessor.doFilter(BasicHeaderProcessor.java:93)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at org.acegisecurity.context.HttpSessionContextIntegrationFilter.doFilter(HttpSessionContextIntegrationFilter.java:249)
    at hudson.security.HttpSessionContextIntegrationFilter2.doFilter(HttpSessionContextIntegrationFilter2.java:67)
    at hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
    at hudson.security.ChainedServletFilter.doFilter(ChainedServletFilter.java:76)
    at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:171)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
    at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
    at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
    at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
    at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1474)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
    at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:533)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
    at org.eclipse.jetty.server.Server.handle(Server.java:370)
    at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
    at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:949)
    at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1011)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
    at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
    at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)
    at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
    at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)

    Number of locked synchronizers = 1
    - java.util.concurrent.ThreadPoolExecutor$Worker@10bbcda

---

Originally reported by mhulth, imported from: Cannot load job pages due to HistoryWidget hanging

• assignee: djlee
• status: Resolved
• priority: Critical
• resolution: Fixed
• resolved: 2016-08-02T18:39:19+00:00
• imported: 2022/01/10

[timja]

danielbeck:

tfennelly It looks like HistoryPageFilter converts an iterator of all builds to a list, thereby breaking lazy loading carefully implemented in AbstractLazyLoadRunMap. Or am I misreading this?

[timja]

clkao:

This has affected the latest LTS (1.642.1) and rendered jobs with 2000+ builds not responsive

[timja]

tfennelly:

danielbeck I don't think HistoryPageFilter is the issue as it's only short lived object (during rendering) + it only ever holds maxEntries, which is typically just 30.

[timja]

danielbeck:

tfennelly Thanks for the update. Would still appreciate if you could take a closer look some time this month.

[timja]

gregmallett:

Tom FENNELLY, the toList() call mentioned by Daniel Beck is not in HistoryPageFilter, but is in the BuildHistoryWidget. From his stack trace:

hudson.widgets.BuildHistoryWidget.getHistoryPageFilter(BuildHistoryWidget.java:81)

I have a very similar stack trace and had opened a duplicate of this ticket reporting the same issue: https://issues.jenkins-ci.org/browse/JENKINS-31888.

[timja]

djlee:

I have a change that updates the logic in BuildHistoryWidget and HistoryPageFilter to avoid serializing the entire list of jobs to a List. Will send a pull request soon after a bit more testing.

[timja]

djlee:

Sent a pull request: https://github.com/jenkinsci/jenkins/pull/2456

[timja]

leedega:

Has anyone confirmed whether or not the use of the MultiJob plugin plays a role in this performance problem? Based on a somewhat superficial review of the build records for jobs of this type, it would appear as though that plugin creates custom build records which recursively reference children jobs of the parent. I also suspect that the sub-builds are being loaded when querying the build history of the parent as well, meaning there may be dozens of XML file accesses for each build item for jobs of this type.

If my assumptions prove correct, perhaps a related defect should be created to find some way to optimize the MultiJob plugin to avoid these nested queries.

[timja]

leedega:

Also, I would assume that the size of the build logs (aka: build.xml) for each build loaded by the HistoryWidget would affect the overall impact of this problem. For example, in our use case I suspect this seemingly unrelated defect combined with jobs of type MultiJob exacerbates this problem even further.

For example, in our use case our build.xml files for some of our jobs are growing to 5-10MB or more, per build. Closer examination of these files reveals that most of this data (~90%) is isolated to the BuildData section described by JERKINS-19022. However, as if that wasn't bad enough, MultiJob jobs apparently have sub-sections for each child job they link to, and each of those children has it's own copy of the Git BuildData as well. For MultiJobs with many sub-jobs the impacts of this problem seem obvious. This behaviour is recursive as well, in cases where multijobs are managed by other multijobs.

I believe these are independent problems that are subtly affecting one another, so the sooner they can be fixed the better.

[timja]

scm_issue_link:

Code changed in jenkins
User: DJ Lee
Path:
core/src/main/java/hudson/widgets/BuildHistoryWidget.java
core/src/main/java/hudson/widgets/HistoryWidget.java
core/src/main/java/jenkins/widgets/HistoryPageFilter.java
core/src/test/java/jenkins/widgets/HistoryPageFilterTest.java
http://jenkins-ci.org/commit/jenkins/55203ebeed1b7e182878d3e3c1184ac042f20473
Log:
[FIXED JENKINS-31791] Optimize BuildHistoryWidget (#2456)

• [FIXED JENKINS-31791] Optimize BuildHistoryWidget

Refactor HistoryPageFilter to lazily evaluate an iterable of previous
runs, instead of instantiating a super long list of builds.
Instantiating the whole list can be problematic with lots of
historical builds especially if disk IO is slow.

[timja]

djlee:

leedega in my company's Jenkins instance, we were having problems like this with MultiJob and without, as long as there were a ton of builds in the history. Our Jenkins master is on an AWS instance with EBS disk, so the I/O is a bit slower than a physical machine, which is probably a contributing factor.

The fix for above will be included in Jenkins 2.17.

[timja]

djlee:

olivergondza May I ask why you removed the lts-candidate tag from this issue? My company is still waiting for an LTS build containing this fix. Is there anything I can do to help get this considered or merged to the LTS branch?

[timja]

olivergondza:

djlee, because the fix was naturally absorbed by the next LTS line based on 2.17. RC to be pushed today.

[timja]

djlee:

olivergondza aha - thanks for explaining!

[timja]

[Originally duplicated by: JENKINS-31663]

[timja]

[Originally duplicated by: JENKINS-34526]

[timja]

[Originally duplicated by: JENKINS-31888]