Performance profiling tools for shell scripts

Question

I'm attempting to speed up a collection of scripts that invoke subshells and do all sorts of things. I was wonder if there are any tools available to time the execution of a shell script and its nested shells and report on which parts of the script are the most expensive.

For example, if I had a script like the following.

#!/bin/bash

echo "hello"
echo $(date)
echo "goodbye"

I would like to know how long each of the three lines took. time will only only give me total time for the script. bash -x is interesting but does not include timestamps or other timing information.

Answer 1

You can set PS4 to show the time and line number. Doing this doesn't require installing any utilities and works without redirecting stderr to stdout.

For this script:

#!/bin/bash -x
# Note the -x flag above, it is required for this to work
PS4='+ $(date "+%s.%N ($LINENO) ")'
for i in {0..2}
do
    echo $i
done
sleep 1
echo done

The output looks like:

+ PS4='+ $(date "+%s.%N ($LINENO) ")'
+ 1291311776.108610290 (3) for i in '{0..2}'
+ 1291311776.120680354 (5) echo 0
0
+ 1291311776.133917546 (3) for i in '{0..2}'
+ 1291311776.146386339 (5) echo 1
1
+ 1291311776.158646585 (3) for i in '{0..2}'
+ 1291311776.171003138 (5) echo 2
2
+ 1291311776.183450114 (7) sleep 1
+ 1291311777.203053652 (8) echo done
done

This assumes GNU date, but you can change the output specification to anything you like or whatever matches the version of date that you use.

Note: If you have an existing script that you want to do this with without modifying it, you can do this:

PS4='+ $(date "+%s.%N ($LINENO) ")' bash -x scriptname

In the upcoming Bash 5, you will be able to save forking date (but you get microseconds instead of nanoseconds):

PS4='+ $EPOCHREALTIME ($LINENO) '

Answer 2

You could pipe the output of running under -x through to something that timestamps each line when it is received. For example, tai64n from djb's daemontools. At a basic example,

sh -x slow.sh 2>&1 | tai64n | tai64nlocal

This conflates stdout and stderr but it does give everything a timestamp. You'd have to then analyze the output to find expensive lines and correlate that back to your source.

You might also conceivably find using strace helpful. For example,

strace -f -ttt -T -o /tmp/analysis.txt slow.sh

This will produce a very detailed report, with lots of timing information in /tmp/analysis.txt, but at a per-system call level, which might be too detailed.

Answer 3

Sounds like you want to time each echo. If echo is all that you're doing this is easy

alias echo='time echo'

If you're running other command this obviously won't be sufficient.

Answer 4

Updated

See enable_profiler/disable_profiler in https://github.com/vlovich/bashrc-wrangler/blob/master/bash.d/000-setup

which is what I use now. I haven't tested on all version of BASH & specifically but if you have the ts utility installed it works very well with low overhead.

Old

My preferred approach is below. Reason is that it supports OSX as well (which doesn't have high precision date) & runs even if you don't have bc installed.

#!/bin/bash

_profiler_check_precision() {
    if [ -z "$PROFILE_HIGH_PRECISION" ]; then
        #debug "Precision of timer is unknown"
        if which bc > /dev/null 2>&1 && date '+%s.%N' | grep -vq '\.N$'; then
            PROFILE_HIGH_PRECISION=y
        else
            PROFILE_HIGH_PRECISION=n
        fi
    fi
}


_profiler_ts() {
    _profiler_check_precision

    if [ "y" = "$PROFILE_HIGH_PRECISION" ]; then
        date '+%s.%N'
    else
        date '+%s'
    fi
}

profile_mark() {
    _PROF_START="$(_profiler_ts)"
}

profile_elapsed() {
    _profiler_check_precision

    local NOW="$(_profiler_ts)"
    local ELAPSED=

    if [ "y" = "$PROFILE_HIGH_PRECISION" ]; then
        ELAPSED="$(echo "scale=10; $NOW - $_PROF_START" | bc | sed 's/\(\.[0-9]\{0,3\}\)[0-9]*$/\1/')"
    else
        ELAPSED=$((NOW - _PROF_START))
    fi

    echo "$ELAPSED"
}

do_something() {
    local _PROF_START
    profile_mark
    sleep 10
    echo "Took $(profile_elapsed) seconds"
}

Answer 5

Here's a simple method that works on almost every Unix and needs no special software:

• enable shell tracing, e.g. with set -x
• pipe the output of the script through logger:

sh -x ./slow_script 2>&1 | logger

This will writes the output to syslog, which automatically adds a time stamp to every message. If you use Linux with journald, you can get high-precision time stamps using

journalctl -o short-monotonic _COMM=logger

Many traditional syslog daemons also offer high precision time stamps (milliseconds should be sufficient for shell scripts).

Here's an example from a script that I was just profiling in this manner:

[1940949.100362] bremer root[16404]: + zcat /boot/symvers-5.3.18-57-default.gz
[1940949.111138] bremer root[16404]: + '[' -e /var/tmp/weak-modules2.OmYvUn/symvers-5.3.18-57-default ']'
[1940949.111315] bremer root[16404]: + args=(-E $tmpdir/symvers-$krel)
[1940949.111484] bremer root[16404]: ++ /usr/sbin/depmod -b / -ae -E /var/tmp/weak-modules2.OmYvUn/symvers-5.3.18-57-default 5.3.18-57>
[1940952.455272] bremer root[16404]: + output=
[1940952.455738] bremer root[16404]: + status=0

where you can see that the "depmod" command is taking a lot of time.

Answer 6

Copied from here:

Since I've ended up here at least twice now, I implemented a solution:

https://github.com/walles/shellprof

It runs your script, transparently clocks all lines printed, and at the end prints a top 10 list of the lines that were on screen the longest:

~/s/shellprof (master|✔) $ ./shellprof ./testcase.sh
quick
slow
quick

Timings for printed lines:
1.01s: slow
0.00s: <<<PROGRAM START>>>
0.00s: quick
0.00s: quick
~/s/shellprof (master|✔) $

Answer 7

I'm not aware of any shell profiling tools.

Historically one just rewrites too-slow shell scripts in Perl, Python, Ruby, or even C.

A less drastic idea would be to use a faster shell than bash. Dash and ash are available for all Unix-style systems and are typically quite a bit smaller and faster.