[JIRA] (JENKINS-61402) Jenkins Docker Start Up Very Slow

[bpham@highfive.com (JIRA)]

Brian Pham created an issue

Jenkins / JENKINS-61402 Jenkins Docker Start Up Very Slow Issue Type: Bug Assignee: Unassigned Components: core Created: 2020-03-09 16:30 Environment: Docker (jenkins/jenkins:lts-slim)Jenkins 2.204.5 Operation System: CoreOS 2247.7.0 Plugins All Running Latest antisamy-markup-formatter build-timeout cloudbees-folder credentials-binding email-ext git github-branch-source gradle ldap mailer matrix-auth pam-auth pipeline-github-lib pipeline-stage-view ssh-slaves timestamper workflow-aggregator ws-cleanup ansible ansicolor artifactory blueocean build-flow-plugin:0.20 build-flow-test-aggregator:1.2 build-name-setter build-user-vars-plugin build-with-parameters buildgraph-view console-column-plugin cygpath date-parameter description-column-plugin downstream-buildview ec2-fleet elastic-axis embeddable-build-status ghprb github google-login jobConfigHistory kpp-management-plugin performance phabricator-plugin rebuild role-strategy s3 scala-junit-name-decoder simple-parameterized-builds-report simple-theme-plugin slack test-stability thinBackup throttle-concurrents view-job-filters xvfb Priority: Major Reporter: Brian Pham We have 3 separate Jenkins master machines running on the same version for different environments and all configured the same exact way. We are noticing that one of the Jenkins master node is starting up very slowly up to 30+ before it fully starts up. The other 2 machines start up fairly quickly. I am trying to look in the logs, but not seeing anything that stands out. CPU / mem usage seems very low.    This is what I am seeing in the logs. Is there anything else I can look to see why after Jenkins initialized it takes so long? In the logs, I can see it went from 2.204.4 to 2.204.5, but it takes another 30mins to see it do something else.  Mar 09 15:37:42 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:42.676+0000 [id=1] INFO o.e.j.server.session.HouseKeeper#startScavenging: node0 Scavenging every 660000ms Mar 09 15:37:43 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:43.006+0000 [id=1] INFO hudson.WebAppMain#contextInitialized: Jenkins home directory: /var/jenkins_home found at: EnvVars.masterEnvVars.get("JENKINS_HOME") Mar 09 15:37:43 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:43.839+0000 [id=1] INFO o.e.j.s.handler.ContextHandler#doStart: Started w.@62417a16{Jenkins v2.204.5,/,file:///var/cache/jenkins/war/,AVAILABLE}{/var/cache/jenkins/war} Mar 09 15:37:43 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:43.856+0000 [id=1] INFO o.e.j.server.AbstractConnector#doStart: Started ServerConnector@792b749c{HTTP/1.1,[http/1.1]}{0.0.0.0:8080} Mar 09 15:37:43 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:43.857+0000 [id=1] INFO org.eclipse.jetty.server.Server#doStart: Started @3054ms Mar 09 15:37:43 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:43.857+0000 [id=21] INFO winstone.Logger#logInternal: Winstone Servlet Engine v4.0 running: controlPort=disabled Mar 09 15:37:45 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:45.149+0000 [id=20] WARNING jenkins.security.ClassFilterImpl#register: JEP-200 class filtering by whitelist suppressed. Your Jenkins installation may be at risk. See https://jenkins.io/redirect/class-filter/ Mar 09 15:37:45 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:45.236+0000 [id=27] INFO jenkins.InitReactorRunner$1#onAttained: Started initialization Mar 09 15:37:45 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:45.266+0000 [id=26] INFO hudson.PluginManager#loadDetachedPlugins: Upgrading Jenkins. The last running version was 2.204.4. This Jenkins is version 2.204.5. Mar 09 15:37:46 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:46.379+0000 [id=26] INFO hudson.PluginManager#loadDetachedPlugins: Upgraded Jenkins from version 2.204.4 to version 2.204.5. Loaded detached plugins (and dependencies): [] Mar 09 16:06:13 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:06:13.602+0000 [id=31] INFO jenkins.InitReactorRunner$1#onAttained: Listed all plugins Mar 09 16:06:58 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:06:58.632+0000 [id=29] INFO com.sic.plugins.kpp.KPPPlugin#start: starting kpp plugin Mar 09 16:07:51 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:07:51.994+0000 [id=31] INFO jenkins.InitReactorRunner$1#onAttained: Prepared all plugins Mar 09 16:07:52 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:07:52.004+0000 [id=32] INFO jenkins.InitReactorRunner$1#onAttained: Started all plugins Mar 09 16:08:01 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:01.938+0000 [id=26] INFO h.ExtensionFinder$GuiceFinder$FaultTolerantScope$1#error: Failed to instantiate optional component hudson.plugins.build_timeout.operations.AbortAndRestartOperation$DescriptorImpl; skipping Mar 09 16:08:03 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:03.807+0000 [id=32] INFO jenkins.InitReactorRunner$1#onAttained: Augmented all extensions Mar 09 16:08:29 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:29.876+0000 [id=29] INFO hudson.slaves.SlaveComputer#tryReconnect: Attempting to reconnect FA_us-west-1_mac_threadmill Mar 09 16:08:34 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:34.676+0000 [id=33] INFO jenkins.InitReactorRunner$1#onAttained: Loaded all jobs Mar 09 16:08:34 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:34.686+0000 [id=65] INFO hudson.model.AsyncPeriodicWork#lambda$doRun$0: Started Download metadata Mar 09 16:08:35 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:35.207+0000 [id=31] INFO j.util.groovy.GroovyHookScript#execute: Executing /var/jenkins_home/init.groovy.d/set-timezone.groovy Mar 09 16:08:35 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:35.662+0000 [id=28] INFO o.s.c.s.AbstractApplicationContext#prepareRefresh: Refreshing org.springframework.web.context.support.StaticWebApplicationContext@79c86727: display name [Root WebApplicationContext]; startup date [Mon Mar 09 16:08:35 UTC 2020]; root of context hierarchy Mar 09 16:08:35 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:35.663+0000 [id=28] INFO o.s.c.s.AbstractApplicationContext#obtainFreshBeanFactory: Bean factory for application context [org.springframework.web.context.support.StaticWebApplicationContext@79c86727]: org.springframework.beans.factory.support.DefaultListableBeanFactory@2a88b885 Mar 09 16:08:35 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:35.673+0000 [id=28] INFO o.s.b.f.s.DefaultListableBeanFactory#preInstantiateSingletons: Pre-instantiating singletons in org.springframework.beans.factory.support.DefaultListableBeanFactory@2a88b885: defining beans [filter,legacy]; root of factory hierarchy Mar 09 16:08:36 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:36.392+0000 [id=31] INFO j.util.groovy.GroovyHookScript#execute: Executing /var/jenkins_home/init.groovy.d/tcp-slave-agent-port.groovy Mar 09 16:08:36 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:36.748+0000 [id=65] INFO hudson.util.Retrier#start: Attempt #1 to do the action check updates server Mar 09 16:08:42 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:42.274+0000 [id=65] INFO hudson.model.UpdateSite#updateData: Obtained the latest update center data file for UpdateSource default Mar 09 16:08:47 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: --> setting agent port for jnlp Mar 09 16:08:55 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: --> setting agent port for jnlp... done Mar 09 16:08:55 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:08:55.911+0000 [id=28] INFO jenkins.InitReactorRunner$1#onAttained: Completed initialization   Add Comment

This message was sent by Atlassian Jira (v7.13.12#713012-sha1:6e07c38)

[o.v.nenashev@gmail.com (JIRA)]

Oleg Nenashev commented on JENKINS-61402

Re: Jenkins Docker Start Up Very Slow Looks like it is something related to plugin loading and, maybe, their initialization handlers. It would be great to have this timeframe with FINEST logging so that we could pin-point the root cause

Mar 09 15:37:46 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 15:37:46.379+0000 [id=26] INFO hudson.PluginManager#loadDetachedPlugins: Upgraded Jenkins from version 2.204.4 to version 2.204.5. Loaded detached plugins (and dependencies): [] Mar 09 16:06:13 ip-10-0-2-71.us-west-2.compute.internal docker[15997]: 2020-03-09 16:06:13.602+0000 [id=31] INFO jenkins.InitReactorRunner$1#onAttained: Listed all plugins

Add Comment

[o.v.nenashev@gmail.com (JIRA)]

Oleg Nenashev updated an issue

Jenkins / JENKINS-61402

Jenkins Docker Start Up Very Slow

Change By: Oleg Nenashev Component/s: _unsorted Component/s: core

Add Comment