Bash execution timeline for Jenkins scripts

Reading Time: 3 minutes

Have you ever wondered why your bash script in Jenkins suddenly runs so damn slow? Let’s say you have a job that downloads some source code, compiles it and runs some tests. Someday it takes ages to finish and you don’t know why. Wouldn’t it be lovely to have a timeline of bash commands?

Jenkins provides a nice “trend” for job durations:

Jenkins build time trend

That helps to spot that something is slowing. The latest build takes more than a minute longer than before. But why?

We want to know what command has become slower. Is the source code repository slow? Did the Spectre/Meltdown patches slow down your build? Is it the 12000 test cases you made the intern write?

Sure, we could insert some date calls in the bash script to get a timeline of the command execution. But do you still want to do that if your build script consists of 200 lines of shell code?

Magic Variables to the rescue!

Bash uses a special Prompt String when in Debug mode (set -x): PS4

Similar to the $PS1 variable that you have probably pimped with __git_ps1, bash evals the content of $PS4 variable before the command is echoed. The default value is +.

We need some code to play with. Paste this into test.sh:

Execute it with bash -x (which does the same as calling set -x inside the script):

Let’s see, which command is slowing down the execution 🙂

Wow! We are losing a whole second in the line that reads sleep 1. Problem solved.

Use in Jenkins

Back in Jenkins, we don’t need to call sh -x or set -x because Jenkins does that for us (even with the helpful -e option).

All we need to do is set our timeline prompt at the beginning of our build script:

That’s it. Good luck finding your snail process!

If you have trouble getting it to work, come back and read the rest of article 🙂

Gotchas

Quoting

It’s bash – s you need to be aware of quoting! If you use a sub-shell in your PS4 make sure it is not executed when setting the variable.

In this example, I took the sub-shell out of the single quotes. Notice how the timestamp does not change after the sleep:

There are various ways of quoting in bash that prevents the code in PS4 from being executed on assignment. For example:

You can test if your prompt works as expected with

Sub shells

Sub-shells are a very useful and powerful feature and many bash scripts use them. The debug output of -x can look confusing when sub-shells are executed. To hint you at the nesting level, bash repeats the first character of the debug prompt for each level.

Consider the following command:

When we execute it with our favourite time-aware PS4 from above, it will look like this:

This is nothing to worry about, but it may look strange at first sight.

Image: Angry Jenkins by Masanobu Imai under the CC BY-SA 3.0 license from jenkins.io

3 Comments

  • What is the advantage of this over using the console log timestamp plugin?

  • Hey, you’re right! The plugin (can you share a link?) probably does the same. My intention was to show a useful scenario for PS4, which happened to be Jenkins. Your plugin may be more comfortable in Jenkins. But there may be more use cases for PS4 somewhere else 🙂 Cheers!

Leave a Comment

Your email address will not be published.