jenkins UI hanging on job page, threads blocked
725 views
Skip to first unread message
Kevin Goess
Sep 25, 2015, 12:08:26 PM9/25/15
to Jenkins Users
| For one one our builds, if we try to load a job page like /job/www/12345/, the browser would hang forever and the jenkins /monitoring page would show the thread blocked on TestResultAction | |||||||
| Handling GET /job/www/43365/ from x.x.x.x : RequestHandlerThread[#17] AbstractBuild/index.jelly AbstractTestResultAction/summary.jelly yes 5 BLOCKED hudson.tasks.junit.TestResultAction.getResult(TestResultAction.java:135) The stacktrace looked like this: |
Handling GET /job/www/43365/ from x.x.x.x : RequestHandlerThread[#17] AbstractBuild/index.jelly AbstractTestResultAction/summary.jelly
hudson.tasks.junit.TestResultAction.getResult(TestResultAction.java:135)
hudson.tasks.junit.TestResultAction.getFailedTests(TestResultAction.java:186)
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:606)
org.apache.commons.jexl.util.PropertyExecutor.execute(PropertyExecutor.java:125)
org.apache.commons.jexl.util.introspection.UberspectImpl$VelGetterImpl.invoke(UberspectImpl.java:314)
org.apache.commons.jexl.parser.ASTArrayAccess.evaluateExpr(ASTArrayAccess.java:185)
org.apache.commons.jexl.parser.ASTIdentifier.execute(ASTIdentifier.java:75)
org.apache.commons.jexl.parser.ASTReference.execute(ASTReference.java:83)
org.apache.commons.jexl.parser.ASTReference.value(ASTReference.java:57)
org.apache.commons.jexl.parser.ASTReferenceExpression.value(ASTReferenceExpression.java:51)
org.apache.commons.jexl.ExpressionImpl.evaluate(ExpressionImpl.java:80)
hudson.ExpressionFactory2$JexlExpression.evaluate(ExpressionFactory2.java:74)
org.apache.commons.jelly.tags.core.CoreTagLibrary$3.run(CoreTagLibrary.java:134)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
org.kohsuke.stapler.jelly.IncludeTag.doTag(IncludeTag.java:147)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161)
org.apache.commons.jelly.tags.core.ForEachTag.doTag(ForEachTag.java:150)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.tags.core.CoreTagLibrary$1.run(CoreTagLibrary.java:98)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.CallTagLibScript$1.run(CallTagLibScript.java:99)
org.apache.commons.jelly.tags.define.InvokeBodyTag.doTag(InvokeBodyTag.java:91)
org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99)
org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95)
org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
org.kohsuke.stapler.jelly.CallTagLibScript.run(CallTagLibScript.java:120)
org.apache.commons.jelly.tags.core.CoreTagLibrary$2.run(CoreTagLibrary.java:105)
org.kohsuke.stapler.jelly.JellyViewScript.run(JellyViewScript.java:95)
org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:63)
org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:53)
org.kohsuke.stapler.jelly.JellyClassTearOff.serveIndexJelly(JellyClassTearOff.java:112)
org.kohsuke.stapler.jelly.JellyFacet.handleIndexRequest(JellyFacet.java:127)
org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:735)
org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
org.kohsuke.stapler.MetaClass$13.dispatch(MetaClass.java:411)
org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:249)
org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:746)
org.kohsuke.stapler.Stapler.invoke(Stapler.java:876)
org.kohsuke.stapler.Stapler.invoke(Stapler.java:649)
org.kohsuke.stapler.Stapler.service(Stapler.java:238)
javax.servlet.http.HttpServlet.service(HttpServlet.java:848)
org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:686)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1494)
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:132)
hudson.plugins.greenballs.GreenBallFilter.doFilter(GreenBallFilter.java:58)
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:129)
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:198)
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:176)
net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:85)
org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:99)
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:129)
hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:123)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:92)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
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)
jenkins.security.BasicHeaderProcessor.doFilter(BasicHeaderProcessor.java:93)
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:171)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1482)
org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30)
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1474)
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:499)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:533)
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:428)
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)
org.eclipse.jetty.server.Server.handle(Server.java:370)
org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:489)
org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:949)
org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1011)
org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)
org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)
org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)
org.eclipse.jetty.io.nio.SslConnection.handle(SslConnection.java:196)
org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:668)
org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:52)
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:745)
Handling GET /job/www/43365/ from x.x.x.x : RequestHandlerThread[#17] AbstractBuild/index.jelly AbstractTestResultAction/summary.jelly yes 5 BLOCKEDBLOCKED hudson.tasks.junit.TestResultAction.getResult(TestResultAction.java:135) 839 820 Kill the thread Handling GET /job/www/43365/ from x.x.x.x : RequestHandlerThread[#17] AbstractBuild/index.jelly AbstractTestResultAction/summary.jelly
Handling GET /job/www/43365/ from x.x.x.x : RequestHandlerThread[#18] AbstractBuild/index.jelly AbstractTestResultAction/summary.jelly
Upgrading to jenkins 1.630 didn't help. Removing all the existing jobs *did* help. It was only this one build--all the other builds are fine. So we're unstuck now, I'm posting this here in case somebody's seen this before and has a hint for if it comes up again.
Baptiste Mathus
Sep 25, 2015, 2:52:53 PM9/25/15
to jenkins...@googlegroups.com
In that case, to improve data for future reference, could you post the JUnit Plugin version you're using?
Thanks
--
You received this message because you are subscribed to the Google Groups "Jenkins Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jenkinsci-use...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/jenkinsci-users/91d61863-3f5f-4da9-acd4-7ae3b783d218%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
brother kevin
Sep 29, 2015, 2:09:46 PM9/29/15
to Jenkins Users, bma...@batmat.net
The problem returned after changing the max builds back to 500 for the job in question. We kept upping the -Xmx value and jenkins continued to run out of memory and the web ui would become unusable, with most requests timing out.
We eventually settled on -Xmx16384M and the jenkins monitoring plugin showed the junit xml processing cresting the 16GB watermark.
We upgraded from v1.8 of the junit plugin, to the latest version v1.9, and experienced the same excessive memory usage.
The junit.xml file has includes 51,000 tests and is about 17MB in size. Is that indicative of a job that has too many tests within it?
Please advise, we have turned off junit processing on the job in question and our memory usage has dropped to below 4GB.
Thank you!
brother kevin
Oct 14, 2015, 11:40:16 AM10/14/15
to Jenkins Users, bma...@batmat.net
To follow-up on this thread for anyone who is experiencing similar issues with junit processing and memory usage -
Firstly, we noticed that a specific set of pages were taking the longest to load - the interstitial build number pages that show changes, scm revisions, and a Test Result link (e.g. https://jenkins/job/myjob/43980/).
Secondly, we noticed that the longer the job ran without someone actively loading one of the interstitial build pages, the worse the problem became. For example, attempting to load one of these pages after a weekend with no activity could take upwards of a minute.
Finally, if the most recent interstitial job page was loaded by a single user, all of the other pages then became responsive for all users.
Our workaround for the time being is a cron job that pre-loads these interstitial pages using curl. We were pleasantly surprised this worked at all and we are anxious to better understand what is causing this new blocking behavior.
0 * * * * jenkins lastBuild=`ls -ltr /var/lib/jenkins/jobs/myjob/builds | tail -1 | awk '{print $9}'`; curl -k https://jenkins/job/myjob/$lastBuild/ > /tmp/$lastBuild.output
brother kevin
Nov 5, 2015, 1:18:12 PM11/5/15
to Jenkins Users, bma...@batmat.net
So our curl job helped to mask the issue, but eventually it too started backing up, unable to keep up with the slowdown. It appears that this issue evidences itself every time garbage collection occurs.
We are using the junit plugin v1.9 (https://wiki.jenkins-ci.org/display/JENKINS/JUnit+Plugin) to provide graph and convenient links to test failures. This plugin appears to be at the heart of the slowdown, but it isn't clear to us WHY these chains of reads are happening in the first place. Also note we save 500 builds for each job and would save more if it was feasible.
So, lets manually trigger a garbage collection and then go visit two interstitial build pages (e.g. https://jenkins/jobs/job1/1234/ and https://jenkins/jobs/job2/3456)
Now lets run the following strace against the pid of the jenkins java processon our CentOS install -
strace -p <jenkins pid> -f -e trace='!futex' -s1000 -e trace='open' 2>&1 | grep 'jobs'
OUTPUT:
[pid 1000] 16:45:21 open("/var/lib/jenkins/jobs/job1/builds/1234/junitResult.xml", O_RDONLY) = 487
[pid 2000] 16:45:24 open("/var/lib/jenkins/jobs/job2/builds/3456/junitResult.xml", O_RDONLY) = 483
[pid 1000] 16:45:26 open("/var/lib/jenkins/jobs/job1/builds/1233/junitResult.xml", O_RDONLY) = 487
[pid 2000] 16:45:28 open("/var/lib/jenkins/jobs/job2/builds/3455/junitResult.xml", O_RDONLY) = 483
It will continue to do this for all 500 builds for each job, spinning up another java thread for each job, starting a cycle lasting ~41 minutes (500 builds, 5 seconds each). Remember, this was triggered by visiting a single interstitial job page for each job. What is it doing?
It appears to be opening each 16MB junit.xml file and parsing it... but for what purpose?
strace of pid that is opening each 16MB junit.xml -
[pid 21366] 16:50:46 fstat(177, {st_mode=S_IFREG|0644, st_size=18788419, ...}) = 0
[pid 21366] 16:50:46 lseek(177, 0, SEEK_CUR) = 10403840
[pid 21366] 16:50:46 lseek(177, 0, SEEK_END) = 18788419
[pid 21366] 16:50:46 lseek(177, 10403840, SEEK_SET) = 10403840
[pid 21366] 16:50:46 read(177, "8K of XML DATA
[pid 21366] 16:50:46 fstat(177, {st_mode=S_IFREG|0644, st_size=18788419, ...}) = 0
[pid 21366] 16:50:46 lseek(177, 0, SEEK_CUR) = 10412032
[pid 21366] 16:50:46 lseek(177, 0, SEEK_END) = 18788419
[pid 21366] 16:50:46 lseek(177, 10412032, SEEK_SET) = 10412032
[pid 21366] 16:50:46 read(177, "NEXT 8K OF XML FILE
We have temporarily reduced the pain caused by this issue by reducing the number of saved builds from 500 to 50, but we would love to find a fix or better understand what is happening.
Thanks!
Kevin*2
Reply all
Reply to author
Forward
0 new messages