How can I profile a shell script?

Question

I have several programs that I'm executing in a shell script:

./myprogram1
./myprogram2
...

I know that I can profile each individual program by editing the source code, but I wanted to know if there was a way I could measure the total time executed by profiling the script itself. Is there a timer program that I can use for this purpose? If so, how precise is its measurement?

Answer 1

Start by using time as per Jon Lin's suggestion:

$ time ls test
test

real    0m0.004s
user    0m0.002s
sys     0m0.002s

You don't say what unix your scripts are running on but strace on linux, truss on Solaris/AIX, and I think tusc on hp-ux let you learn a lot about what a process is doing. I like strace's -c option to get a nice summary:

]$ strace -c ls
test
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 89.19    0.000998         998         1           execve
 10.81    0.000121         121         1           write
  0.00    0.000000           0        12           read
  0.00    0.000000           0        93        79 open
  0.00    0.000000           0        16           close
  0.00    0.000000           0         2         1 access
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         4           munmap
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         6           mprotect
  0.00    0.000000           0         2           rt_sigaction
  0.00    0.000000           0         1           rt_sigprocmask
  0.00    0.000000           0         1           getrlimit
  0.00    0.000000           0        30           mmap2
  0.00    0.000000           0         8         7 stat64
  0.00    0.000000           0        13           fstat64
  0.00    0.000000           0         2           getdents64
  0.00    0.000000           0         1           fcntl64
  0.00    0.000000           0         1           futex
  0.00    0.000000           0         1           set_thread_area
  0.00    0.000000           0         1           set_tid_address
  0.00    0.000000           0         1           set_robust_list
  0.00    0.000000           0         1           socket
  0.00    0.000000           0         1         1 connect
------ ----------- ----------- --------- --------- ----------------
100.00    0.001119                   205        88 total

Do also note that attaching these tracing type programs can slow the program down somewhat.

Answer 2

It's not exactly profiling, but you can trace your script as it runs. Put set -xv before the section you want to trace and set +xv after the section. set -x enables xtrace, which will show every line that executes. set -v enables verbose mode, which will also show lines that may have an effect, but are not executed, such as variable assignment.

You can also timestamp your trace. You need a terminal emulator that can timestamp every line; the only one I know of is RealTerm, which is a Windows program, but it will work with Wine. You might also be able to use grabserial, although I've not tried it except with real serial ports. You can find out what serial device your shell is using by running ps -p $$ (if it doesn't, use man to find out how to include the TTY column in your ps output).

Also, see Performance profiling tools for shell scripts on Stack Overflow.

Answer 3

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 4

Check out the time command. You can use it to measure the time it takes to execute along with some other useful info like where the time is being spent.

Answer 5

time for several iterations

Profiling by running the same command multiple times

time (for ((n=0;n<10;n++)); do echo "scale=1000; 4*a(1)" | bc -l; done)

Where echo "scale=1000; 4*a(1)" | bc -l computes pi and time (...) ensures that the for loop runs as a single command.

Answer 6

Just wrote a simple Tcl script (Tcl is probably pre-installed in a unix system),

https://github.com/LuxxxLucy/bperf

basically we add the PS4 trace to the script and then run it, then we processed it into a perf.script which you can then visualize, say, by the online Firefox Profiler.

It is rough work but is good enough for my intended use case

Answer 7

If you want to manually add some logging statements at key points in your script, you could include the following function in your bash script.

Note that it takes some time (~ 50 ms) to shell out to python to get the current timestamp, so using this will increase run times slightly, but will help you easily log time between commands in your script.

function traceTick(){
  local CURR_TIME=$(python -c "import time; print(int(time.time()*1000))")
  if [ -z "$LAST_TIME" ]
  then
    START_TIME=$CURR_TIME
    LAST_TIME=$CURR_TIME
  fi

  local DELTA=$(($CURR_TIME - $LAST_TIME))
  local TOTAL_DELTA=$(($CURR_TIME - $START_TIME))
  LAST_TIME=$CURR_TIME

  printf "elapsed(ms):%-6s delta(ms):%-6s %s\n" $TOTAL_DELTA $DELTA "$1"
}

Using it in a script like so

traceTick 'starting'
...
traceTick 'did something'
...
traceTick 'more stuff'

will output something like the following

elapsed(ms):0      delta(ms):0      starting
elapsed(ms):2597   delta(ms):2597   did something
elapsed(ms):6560   delta(ms):3963   more stuff