Issue
-
I have activated the startup performance logs with
-Djenkins.model.Jenkins.logStartupPerformance=true -
How can I use / analyze those logs ?
Environment
-
Linux environment
-
CloudBees CI (CloudBees Core) on modern cloud platforms - Managed controller
-
CloudBees CI (CloudBees Core) on modern cloud platforms - Operations Center
-
CloudBees CI (CloudBees Core) on traditional platforms - Client controller
-
CloudBees CI (CloudBees Core) on traditional platforms - Operations Center
-
CloudBees Jenkins Enterprise
-
CloudBees Jenkins Enterprise - Managed controller
-
CloudBees Jenkins Enterprise - Operations center
Resolution
The startup performance logs, activated with the startup argument: -Djenkins.model.Jenkins.logStartupPerformance=true, record additional information of how much time Jenkins spend loading components on startup.
On the next Jenkins startup you will see logs like the following on startup:
2017-07-19 04:36:32.598+0000 [id=55] INFO jenkins.model.Jenkins$7#runTask: Took 5487ms for GroovyInitScript.init by pool-9-thread-10 2017-07-19 04:36:35.188+0000 [id=54] INFO jenkins.model.Jenkins$7#runTask: Took 8078ms for CloudBeesAssurance.initialize by pool-9-thread-9 2017-07-19 04:36:35.213+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 0ms for item listener jenkins.triggers.ReverseBuildTrigger$ItemListenerImpl startup 2017-07-19 04:36:35.213+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 0ms for item listener org.jenkinsci.main.modules.sshd.ItemListenerImpl startup 2017-07-19 04:36:35.213+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 0ms for item listener org.jenkinsci.plugins.pipeline.milestone.MilestoneStepExecution$CleanupJobsOnDelete startup 2017-07-19 04:36:35.215+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 2ms for item listener org.jenkinsci.plugins.workflow.flow.FlowExecutionList$ItemListenerImpl startup 2017-07-19 04:36:35.215+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 0ms for item listener hudson.model.Job$LastItemListener startup 2017-07-19 04:36:35.215+0000 [id=43] INFO jenkins.model.Jenkins#<init>: Took 15796ms for complete Jenkins startup
You can then extract relevant information from the Jenkins logs and find out what are the most costly components / processes on startup. For example, the following command extract each startup log record and sorts them by amount of time (ascending):
grep "Took [0-9]*ms" jenkins.log | sed 's/.*Took \([0-9]*\)ms \(.*\)/\1:\2/' | sort -t ':' -k1,1n
With this command we can identify costly components / plugin on startup. Example of an output:
[...] 11363:for Loading item FolderA by pool-9-thread-8 11519:for Initializing plugin cloudbees-license by pool-9-thread-10 13425:for Loading item SuperPipeline2 by pool-9-thread-12 16692:for Loading item SuperPipeline1 by pool-9-thread-2 27410:for Loading item SuperImportantMultibranch by pool-9-thread-15 52045:for Loading item StagingFolder by pool-9-thread-7 65006:for Loading item ProdFolder by pool-9-thread-1 102728:for item listener hudson.plugins.templateproject.ItemListenerImpl startup 296654:for item listener jenkins.plugins.hipchat.upgrade.ConfigurationMigrator startup 502376:for complete Jenkins startup
You will always see the line ${STARTUP_TIME}ms: for complete Jenkins startup at the end. This is the overall startup time of you Jenkins instance.
|
Considerations
While this technique tells us which component takes a lot of time to load on startup, it does not necessarily mean - although it often does - that these components are the direct culprits. It could well be an underlying issue in which case we need to find the correlation. If for example many jobs are identified as taking an awful lot of time to load, it does not necessary mean that these jobs are bad, but we need to look for a correlation (job type, specific step/property, …). Another example could be several plugins components taking a long time to load on startup because they share a dependency that impact them and therefore the dependency is the problem.