Periodically through the day Jenkins decides to peg one of the processors and
not return requests. I cannot figure out what is the cause of this issue.
I've been monitoring the Jenkins log and I see nothing in it around the time it
hangs. If I monitor the cpu usage with nmon, I can reliably predict when
Jenkins is in this weird unresponsive state. One CPU will be pegged at 100%
and the other will be doing nothing. When both cpus start taking work then
Jenkins is usable again. This morning everything was going fine and then I
clicked the link for a job and the issue occurred, with nothing in the log. A
big problem with this is that it appears Jenkins gets so into whatever it is
doing 100% on that one cpu that it drops its ssh connections to the slaves and
builds fail because of that. I've taken a look at the Jenkins monitoring
plugin and can't see anything obviously wrong. My main question is how do I
debug this problem? Where can I get more information about what Jenkins is
doing when it has entered into this unresponsive state? Below are the errors
from the last time it came back and started working again:
Aug 6, 2012 9:34:39 AM winstone.Logger logInternal
SEVERE: Error while serving
http://[address]/view/RC/job/RC_unit/buildHistory/ajax
java.lang.reflect.InvocationTargetException
at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
org.kohsuke.stapler.Function$InstanceFunction.invoke(Function.java:288)
at org.kohsuke.stapler.Function.bindAndInvoke(Function.java:151)
at
org.kohsuke.stapler.Function.bindAndInvokeAndServeResponse(Function.java:90)
at org.kohsuke.stapler.MetaClass$1.doDispatch(MetaClass.java:111)
at
org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:571)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:656)
at org.kohsuke.stapler.MetaClass$12.dispatch(MetaClass.java:384)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:571)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:656)
at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:241)
at
org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:571)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:656)
at org.kohsuke.stapler.MetaClass$6.doDispatch(MetaClass.java:241)
at
org.kohsuke.stapler.NameBasedDispatcher.dispatch(NameBasedDispatcher.java:53)
at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:571)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:656)
at org.kohsuke.stapler.Stapler.invoke(Stapler.java:485)
at org.kohsuke.stapler.Stapler.service(Stapler.java:159)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:45)
at winstone.ServletConfiguration.execute(ServletConfiguration.java:248)
at winstone.RequestDispatcher.forward(RequestDispatcher.java:333)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:376)
at
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:95)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:197)
at
net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:171)
at
net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:86)
at
org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:84)
at
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:98)
at
hudson.plugins.audit_trail.AuditTrailFilter.doFilter(AuditTrailFilter.java:66)
at
hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:98)
at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:87)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:47)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
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
org.acegisecurity.ui.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:166)
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
org.acegisecurity.ui.basicauth.BasicProcessingFilter.doFilter(BasicProcessingFilter.java:173)
at
hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
at jenkins.security.ApiTokenFilter.doFilter(ApiTokenFilter.java:61)
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:66)
at
hudson.security.ChainedServletFilter$1.doFilter(ChainedServletFilter.java:87)
at
hudson.security.ChainedServletFilter.doFilter(ChainedServletFilter.java:76)
at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:164)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
at
hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:81)
at winstone.FilterConfiguration.execute(FilterConfiguration.java:194)
at winstone.RequestDispatcher.doFilter(RequestDispatcher.java:366)
at winstone.RequestDispatcher.forward(RequestDispatcher.java:331)
at
winstone.RequestHandlerThread.processRequest(RequestHandlerThread.java:215)
at winstone.RequestHandlerThread.run(RequestHandlerThread.java:138)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at winstone.BoundedExecutorService$1.run(BoundedExecutorService.java:77)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: winstone.ClientSocketException: Failed to write to client
at winstone.ClientOutputStream.write(ClientOutputStream.java:41)
at winstone.WinstoneOutputStream.commit(WinstoneOutputStream.java:181)
at winstone.WinstoneOutputStream.flush(WinstoneOutputStream.java:219)
at winstone.WinstoneOutputStream.close(WinstoneOutputStream.java:229)
at
net.bull.javamelody.FilterServletOutputStream.close(FilterServletOutputStream.java:46)
at
java.util.zip.DeflaterOutputStream.close(DeflaterOutputStream.java:149)
at java.io.FilterOutputStream.close(FilterOutputStream.java:143)
at sun.nio.cs.StreamEncoder.implClose(StreamEncoder.java:301)
at sun.nio.cs.StreamEncoder.close(StreamEncoder.java:130)
at java.io.OutputStreamWriter.close(OutputStreamWriter.java:216)
at java.io.BufferedWriter.close(BufferedWriter.java:248)
at org.dom4j.io.XMLWriter.close(XMLWriter.java:286)
at
org.kohsuke.stapler.jelly.HTMLWriterOutput.close(HTMLWriterOutput.java:70)
at
org.kohsuke.stapler.jelly.DefaultScriptInvoker.invokeScript(DefaultScriptInvoker.java:56)
at
org.kohsuke.stapler.jelly.JellyRequestDispatcher.forward(JellyRequestDispatcher.java:55)
at hudson.widgets.HistoryWidget.doAjax(HistoryWidget.java:191)
... 76 more
Caused by: java.net.SocketException: Broken pipe
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:92)
at java.net.SocketOutputStream.write(SocketOutputStream.java:136)
at winstone.ClientOutputStream.write(ClientOutputStream.java:39)
... 91 more
Aug 6, 2012 9:34:40 AM hudson.triggers.SCMTrigger$Runner runPolling
SEVERE: Failed to record SCM polling
hudson.remoting.RequestAbortedException:
hudson.remoting.RequestAbortedException:
hudson.remoting.Channel$OrderlyShutdown: java.util.concurrent.Timeou
tException: Ping started on 1344263361651 hasn't completed at 1344263601654
at hudson.remoting.Request.call(Request.java:149)
at hudson.remoting.Channel.call(Channel.java:646)
at hudson.FilePath.act(FilePath.java:821)
at hudson.FilePath.act(FilePath.java:814)
at hudson.FilePath.exists(FilePath.java:1132)
at
hudson.model.AbstractProject.workspaceOffline(AbstractProject.java:1360)
at hudson.model.AbstractProject.poll(AbstractProject.java:1294)
at hudson.triggers.SCMTrigger$Runner.runPolling(SCMTrigger.java:420)
at hudson.triggers.SCMTrigger$Runner.run(SCMTrigger.java:449)
at
hudson.util.SequentialExecutionQueue$QueueEntry.run(SequentialExecutionQueue.java:118)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:303)
at java.util.concurrent.FutureTask.run(FutureTask.java:138)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: hudson.remoting.RequestAbortedException:
hudson.remoting.Channel$OrderlyShutdown: java.util.concurrent.TimeoutException:
Ping started on 13
44263361651 hasn't completed at 1344263601654
at hudson.remoting.Request.abort(Request.java:273)
at hudson.remoting.Channel.terminate(Channel.java:702)
at hudson.remoting.Channel$CloseCommand.execute(Channel.java:818)
at hudson.remoting.Channel$1.handle(Channel.java:416)
at
hudson.remoting.SynchronousCommandTransport$ReaderThread.run(SynchronousCommandTransport.java:60)
Caused by: hudson.remoting.Channel$OrderlyShutdown:
java.util.concurrent.TimeoutException: Ping started on 1344263361651 hasn't
completed at 134426360
1654
... 3 more
Caused by: Command close created at
at hudson.remoting.Command.<init>(Command.java:54)
at hudson.remoting.Channel$CloseCommand.<init>(Channel.java:812)
at hudson.remoting.Channel$CloseCommand.<init>(Channel.java:810)
at hudson.remoting.Channel.close(Channel.java:877)
at hudson.slaves.ChannelPinger$1.onDead(ChannelPinger.java:110)
at hudson.remoting.PingThread.ping(PingThread.java:114)
at hudson.remoting.PingThread.run(PingThread.java:81)
Caused by: java.util.concurrent.TimeoutException: Ping started on 1344263361651
hasn't completed at 1344263601654
... 2 more
Caused by: java.util.concurrent.TimeoutException
at hudson.remoting.Request$1.get(Request.java:249)
at hudson.remoting.Request$1.get(Request.java:184)
at hudson.remoting.FutureAdapter.get(FutureAdapter.java:59)
at hudson.remoting.PingThread.ping(PingThread.java:107)
... 1 more
