How to analyze Jenkins Startup Performance logs

Issue

  • I have activated the startup performance logs with -Djenkins.model.Jenkins.logStartupPerformance=true
  • How can I use / analyze those logs ?

Environment

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

Note: 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.

References

Have more questions?

0 Comments

Please sign in to leave a comment.