Uploaded image for project: 'Jenkins'
  1. Jenkins
  2. JENKINS-61402

Jenkins Docker Start Up Very Slow

    Details

    • Type: Bug
    • Status: Open (View Workflow)
    • Priority: Major
    • Resolution: Unresolved
    • Component/s: _unsorted
    • Labels:
      None
    • Environment:
    • Similar Issues:

      Description

      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

       

        Attachments

          Activity

          Hide
          oleg_nenashev Oleg Nenashev added a comment -

          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
          
          Show
          oleg_nenashev Oleg Nenashev added a comment - 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

            People

            • Assignee:
              Unassigned
              Reporter:
              red_giant_monster Brian Pham
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: