[JIRA] (JENKINS-60111) Pipeline extremely slow when triggered by a user in comparison with the time triggered pipeline

1 view
Skip to first unread message

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:45:02 AM11/8/19
to jenkinsc...@googlegroups.com
Saad Azam updated an issue
 
Jenkins / Improvement JENKINS-60111
Pipeline extremely slow when triggered by a user in comparison with the time triggered pipeline
Change By: Saad Azam
Attachment: demo_pipeline.jpg
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v7.13.6#713006-sha1:cc4451f)
Atlassian logo

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:45:04 AM11/8/19
to jenkinsc...@googlegroups.com
Saad Azam created an issue
Issue Type: Improvement Improvement
Assignee: Unassigned
Components: pipeline
Created: 2019-11-08 16:44
Environment: Jenkins ver. 2.190.1
Master OS: RedHat Linux
Java version 1.8
Priority: Minor Minor
Reporter: Saad Azam

I recently setup a new Jenkins server on Linux. I am facing issues with the pipeline execution time. I see the pipeline script takes much longer to execute when triggered by a user. On the contrary it is quite fast when built periodically by a time trigger. This is causing a huge overhead for complicated pipelines we are suing in our projects. As an example see the following example pipeline I created for demo:

pipeline {
    agent {label "${NODE_LABEL}"}
    /*
    triggers {
        pollSCM('H/2 * * * *')
    }
    */
    stages {
        stage('One'){
            steps {
                echo 'First stage...'
            }
        }
        stage('Two'){
            steps {
                echo 'Second stage...'
            }
        }
        stage('Three'){
            steps {
                echo 'Third stage...'
            }
        }
        stage('Four'){
            steps {
                echo 'Fourth stage...'
            }
        }
        stage('Five'){
            steps {
                echo 'Fifth stage...'
            }
        }
    }
}

 After looking into the jenkins.log file, the difference I see between the two runs is that at every stage execution in the slower build (executed by the user) there is warning due to an exception in CpsFlowExecution as below:

2019-11-08 16:21:31.222+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Started Download metadata2019-11-08 16:21:31.222+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Started Download metadata2019-11-08 16:21:32.036+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Maven.MavenInstaller2019-11-08 16:21:32.412+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.plugins.gradle.GradleInstaller2019-11-08 16:21:32.686+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Ant.AntInstaller2019-11-08 16:21:33.805+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tools.JDKInstaller2019-11-08 16:21:33.805+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Finished Download metadata. 2,583 ms2019-11-08 16:21:35.616+0000 [id=22366] WARNING o.j.p.w.cps.CpsFlowExecution#blocksRestart: Not blocking restart due to problem checking running steps in CpsFlowExecution[Owner[test_pipeline_general/2:test_pipeline_general #2]]java.util.concurrent.TimeoutException: Timeout waiting for task. at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:259) at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:91) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.blocksRestart(CpsFlowExecution.java:940) at org.jenkinsci.plugins.workflow.job.WorkflowRun$2.blocksRestart(WorkflowRun.java:377) at org.jenkinsci.plugins.workflow.job.WorkflowRun$2.displayCell(WorkflowRun.java:380) at hudson.model.Executor.isDisplayCell(Executor.java:668) at hudson.model.Computer.getDisplayExecutors(Computer.java:1009) at sun.reflect.GeneratedMethodAccessor194.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) 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.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.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99) at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41) 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.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38) 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.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.CallTagLibScript.run(CallTagLibScript.java:120) 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.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.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.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41) at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38) at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269) 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.ScriptInvoker.execute(ScriptInvoker.java:56) at org.kohsuke.stapler.jelly.ScriptInvoker.execute(ScriptInvoker.java:43) at org.kohsuke.stapler.Facet$1.dispatch(Facet.java:238) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:747) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:878) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:815) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:878) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:676) at org.kohsuke.stapler.Stapler.service(Stapler.java:238) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:154) at org.jenkinsci.plugins.ssegateway.Endpoint$SSEListenChannelFilter.doFilter(Endpoint.java:246) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at io.jenkins.blueocean.ResourceCacheControl.doFilter(ResourceCacheControl.java:134) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at io.jenkins.blueocean.auth.jwt.impl.JwtAuthenticationFilter.doFilter(JwtAuthenticationFilter.java:61) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at com.smartcodeltd.jenkinsci.plugin.assetbundler.filters.LessCSS.doFilter(LessCSS.java:47) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:239) at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:215) at net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:88) at org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:114) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at org.jenkinsci.plugins.modernstatus.ModernStatusFilter.doFilter(ModernStatusFilter.java:52) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at jenkins.metrics.impl.MetricsFilter.doFilter(MetricsFilter.java:125) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at hudson.plugins.locale.LocaleFilter.doFilter(LocaleFilter.java:42) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at jenkins.telemetry.impl.UserLanguages$AcceptLanguageFilter.doFilter(UserLanguages.java:128) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:157) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:99) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) 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:90) at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:171) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:505) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427) at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321) at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804) at java.lang.Thread.run(Thread.java:748)

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:48:02 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:48:03 AM11/8/19
to jenkinsc...@googlegroups.com
Saad Azam updated an issue
I recently setup a new Jenkins server on Linux. I am facing issues with the pipeline execution time. I see the pipeline script takes much longer to execute when triggered by a user. On the contrary it is quite fast when built periodically by a time trigger. This is causing a huge overhead for complicated pipelines we are suing in our projects. As an example see the following example pipeline I created for demo (see the attached image for the results) :
{code:java}

pipeline {
    agent {label "${NODE_LABEL}"}
    /*
    triggers {
        pollSCM('H/2 * * * *')
    }
    */
    stages {
        stage('One'){
            steps {
                echo 'First stage...'
            }
        }
        stage('Two'){
            steps {
                echo 'Second stage...'
            }
        }
        stage('Three'){
            steps {
                echo 'Third stage...'
            }
        }
        stage('Four'){
            steps {
                echo 'Fourth stage...'
            }
        }
        stage('Five'){
            steps {
                echo 'Fifth stage...'
            }
        }
    }
}
{code}

 After looking into the jenkins.log file, the difference I see between the two runs is that at every stage execution in the slower build (executed by the user) there is warning due to an exception in CpsFlowExecution as below:
{code:java}

2019-11-08 16:21:31.222+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Started Download metadata2019-11-08 16:21:31.222+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Started Download metadata2019-11-08 16:21:32.036+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Maven.MavenInstaller2019-11-08 16:21:32.412+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.plugins.gradle.GradleInstaller2019-11-08 16:21:32.686+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tasks.Ant.AntInstaller2019-11-08 16:21:33.805+0000 [id=48479] INFO h.m.DownloadService$Downloadable#load: Obtained the updated data file for hudson.tools.JDKInstaller2019-11-08 16:21:33.805+0000 [id=48479] INFO hudson.model.AsyncPeriodicWork$1#run: Finished Download metadata. 2,583 ms2019-11-08 16:21:35.616+0000 [id=22366] WARNING o.j.p.w.cps.CpsFlowExecution#blocksRestart: Not blocking restart due to problem checking running steps in CpsFlowExecution[Owner[test_pipeline_general/2:test_pipeline_general #2]]java.util.concurrent.TimeoutException: Timeout waiting for task. at com.google.common.util.concurrent.AbstractFuture$Sync.get(AbstractFuture.java:259) at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:91) at org.jenkinsci.plugins.workflow.cps.CpsFlowExecution.blocksRestart(CpsFlowExecution.java:940) at org.jenkinsci.plugins.workflow.job.WorkflowRun$2.blocksRestart(WorkflowRun.java:377) at org.jenkinsci.plugins.workflow.job.WorkflowRun$2.displayCell(WorkflowRun.java:380) at hudson.model.Executor.isDisplayCell(Executor.java:668) at hudson.model.Computer.getDisplayExecutors(Computer.java:1009) at sun.reflect.GeneratedMethodAccessor194.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) 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.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.kohsuke.stapler.jelly.ReallyStaticTagLibrary$1.run(ReallyStaticTagLibrary.java:99) at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41) 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.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38) 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.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.CallTagLibScript.run(CallTagLibScript.java:120) 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.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.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.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.OtherwiseTag.doTag(OtherwiseTag.java:41) at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269) at org.apache.commons.jelly.impl.ScriptBlock.run(ScriptBlock.java:95) at org.apache.commons.jelly.TagSupport.invokeBody(TagSupport.java:161) at org.apache.commons.jelly.tags.core.ChooseTag.doTag(ChooseTag.java:38) at org.apache.commons.jelly.impl.TagScript.run(TagScript.java:269) 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.ScriptInvoker.execute(ScriptInvoker.java:56) at org.kohsuke.stapler.jelly.ScriptInvoker.execute(ScriptInvoker.java:43) at org.kohsuke.stapler.Facet$1.dispatch(Facet.java:238) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:747) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:878) at org.kohsuke.stapler.Stapler.tryInvoke(Stapler.java:815) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:878) at org.kohsuke.stapler.Stapler.invoke(Stapler.java:676) at org.kohsuke.stapler.Stapler.service(Stapler.java:238) at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:873) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:154) at org.jenkinsci.plugins.ssegateway.Endpoint$SSEListenChannelFilter.doFilter(Endpoint.java:246) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at io.jenkins.blueocean.ResourceCacheControl.doFilter(ResourceCacheControl.java:134) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at io.jenkins.blueocean.auth.jwt.impl.JwtAuthenticationFilter.doFilter(JwtAuthenticationFilter.java:61) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at com.smartcodeltd.jenkinsci.plugin.assetbundler.filters.LessCSS.doFilter(LessCSS.java:47) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:239) at net.bull.javamelody.MonitoringFilter.doFilter(MonitoringFilter.java:215) at net.bull.javamelody.PluginMonitoringFilter.doFilter(PluginMonitoringFilter.java:88) at org.jvnet.hudson.plugins.monitoring.HudsonMonitoringFilter.doFilter(HudsonMonitoringFilter.java:114) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at org.jenkinsci.plugins.modernstatus.ModernStatusFilter.doFilter(ModernStatusFilter.java:52) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at jenkins.metrics.impl.MetricsFilter.doFilter(MetricsFilter.java:125) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at hudson.plugins.locale.LocaleFilter.doFilter(LocaleFilter.java:42) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at jenkins.telemetry.impl.UserLanguages$AcceptLanguageFilter.doFilter(UserLanguages.java:128) at hudson.util.PluginServletFilter$1.doFilter(PluginServletFilter.java:151) at hudson.util.PluginServletFilter.doFilter(PluginServletFilter.java:157) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at hudson.security.csrf.CrumbFilter.doFilter(CrumbFilter.java:99) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) 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:90) at hudson.security.HudsonFilter.doFilter(HudsonFilter.java:171) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.kohsuke.stapler.compression.CompressionFilter.doFilter(CompressionFilter.java:49) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at hudson.util.CharacterEncodingFilter.doFilter(CharacterEncodingFilter.java:82) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.kohsuke.stapler.DiagnosticThreadNameFilter.doFilter(DiagnosticThreadNameFilter.java:30) at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146) at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257) at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1700) at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1345) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1667) at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1247) at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) at org.eclipse.jetty.server.Server.handle(Server.java:505) at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:427) at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:321) at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:159) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126) at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:698) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:804) at java.lang.Thread.run(Thread.java:748)
{code}

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:49:02 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:49:03 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:49:03 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:50:02 AM11/8/19
to jenkinsc...@googlegroups.com
Saad Azam updated an issue
Change By: Saad Azam
Component/s: pipeline
Component/s: workflow-cps-plugin

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:52:02 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:54:02 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 8, 2019, 11:57:02 AM11/8/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 9, 2019, 6:58:04 PM11/9/19
to jenkinsc...@googlegroups.com
Saad Azam updated an issue
I recently setup a new Jenkins server on Linux. I am facing issues with the pipeline execution time. I see the The pipeline script takes much longer to execute when triggered by a user. On the contrary , it is quite fast when built periodically by a time trigger (This is also the expected behavior) . This is causing a huge overhead for complicated pipelines we are suing using in our projects project . As an example see See the following example pipeline I created for demo (see the attached image for the results):

Saad.Azam@magna.com (JIRA)

unread,
Nov 9, 2019, 6:59:04 PM11/9/19
to jenkinsc...@googlegroups.com
Saad Azam updated an issue
I recently setup a new Jenkins server on Linux. I am facing issues with the pipeline execution time. The pipeline script takes much longer to execute when triggered by a user. On the contrary, it is quite fast when built periodically by a time trigger (This is also the expected behavior). This is causing a huge overhead for complicated pipelines we are using in our project. See the following example pipeline I created for demo (see the attached image for the results):

Saad.Azam@magna.com (JIRA)

unread,
Nov 11, 2019, 5:42:05 AM11/11/19
to jenkinsc...@googlegroups.com

Saad.Azam@magna.com (JIRA)

unread,
Nov 11, 2019, 12:26:02 PM11/11/19
to jenkinsc...@googlegroups.com
Saad Azam commented on Bug JENKINS-60111
 
Re: Pipeline extremely slow when triggered by a user in comparison with the time triggered pipeline

The issue was found to be connected to the "Authorize Project plugin" when using authorization mode "Run as the user who triggered the build". However, we already switched to Role-Based authorization. So after removing the plugin the issue is resolved. But it would be nice to understand the warning occurring in the log I provided and to get insight into the root cause of the behavior.

jglick@cloudbees.com (JIRA)

unread,
Nov 12, 2019, 10:50:02 AM11/12/19
to jenkinsc...@googlegroups.com

jglick@cloudbees.com (JIRA)

unread,
Nov 12, 2019, 10:50:03 AM11/12/19
to jenkinsc...@googlegroups.com

dnusbaum@cloudbees.com (JIRA)

unread,
Nov 14, 2019, 1:20:03 PM11/14/19
to jenkinsc...@googlegroups.com

dnusbaum@cloudbees.com (JIRA)

unread,
Nov 14, 2019, 1:20:04 PM11/14/19
to jenkinsc...@googlegroups.com
Devin Nusbaum commented on Bug JENKINS-60111
 
Re: Pipeline extremely slow when triggered by a user in comparison with the time triggered pipeline

Thanks for the report!

My guess for the reason for the slowdown is that when you ran builds triggered by users as the triggering user using Authorize Project Plugin, permission checks during the course of the build had to interact with your security realm and authorization strategy to figure out what permissions the user had based on your configuration. Builds that are triggered automatically run as the Jenkins SYSTEM user, which always has all permissions, and so permission checks are very quick.

Maybe you could configure more aggressive caching or optimize your LDAP settings or something to improve the performance, depends on how things are configured in your instance. You could take thread dumps while the Pipeline is running slowly and see where threads are usually blocked to confirm/deny my hypothesis.

I'm not sure about the warning. Perhaps the slowdown is significant enough to cause the relevant code to time out. If you aren't seeing it once you remove Authorize Project Plugin, I think you can safely ignore it.

I'm going to close this issue, if you get thread dumps and think there is a bug somewhere based on that data, feel free to reopen it.

Saad.Azam@magna.com (JIRA)

unread,
Nov 15, 2019, 4:03:02 AM11/15/19
to jenkinsc...@googlegroups.com

Devin Nusbaum Thanks for your hypothesis and suggestion. The warning has indeed disappeared after we stopped using Authorize Project Plugin. I will follow your suggestion If I run into the issue again.

jonnydee@gmail.com (JIRA)

unread,
Dec 2, 2019, 1:48:02 AM12/2/19
to jenkinsc...@googlegroups.com

jonnydee@gmail.com (JIRA)

unread,
Dec 2, 2019, 1:50:02 AM12/2/19
to jenkinsc...@googlegroups.com
Jon Denly commented on Bug JENKINS-60111
 
Re: Pipeline extremely slow when triggered by a user in comparison with the time triggered pipeline

For anyone else that comes across this ticket, the following change to the security caching (under Configure Global Security) resolved this performance issue for us.

 

Before the caching was turned on, we saw many threads waiting for LDAP requests, afterwards there were none and Jenkins performance was significantly improved.

"Computer.threadPoolForRemoting [#9537]" Id=2072540 Group=main TIMED_WAITING on com.sun.jndi.ldap.LdapRequest@7ca9d12a
 at java.lang.Object.wait(Native Method)
 - waiting on com.sun.jndi.ldap.LdapRequest@7ca9d12a
 at com.sun.jndi.ldap.Connection.readReply(Connection.java:484)
 at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:632)
 at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:555)
 at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1985)
 at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1844)
 at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1769)
 at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1786)
 at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:418)
 at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:396)
 at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:378)
 at hudson.plugins.active_directory.LDAPSearchBuilder.search(LDAPSearchBuilder.java:120)
 at hudson.plugins.active_directory.ActiveDirectoryUnixAuthenticationProvider.resolveGroups(ActiveDirectoryUnixAuthenticationProvider.java:667)

seancdugan@gmail.com (JIRA)

unread,
Dec 3, 2019, 3:46:05 PM12/3/19
to jenkinsc...@googlegroups.com

aburdajewicz@cloudbees.com (JIRA)

unread,
Feb 21, 2020, 1:24:03 AM2/21/20
to jenkinsc...@googlegroups.com

aburdajewicz@cloudbees.com (JIRA)

unread,
Feb 24, 2020, 8:56:03 PM2/24/20
to jenkinsc...@googlegroups.com
Reply all
Reply to author
Forward
0 new messages