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?
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.
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.
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.
time for several iterationsProfiling 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.
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|✔) $
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"
}
traceTick 'starting'
...
traceTick 'did something'
...
traceTick 'more stuff'
elapsed(ms):0 delta(ms):0 starting
elapsed(ms):2597 delta(ms):2597 did something
elapsed(ms):6560 delta(ms):3963 more stuff
