Higher resolution timers in the shell

© July 2011 Anthony Lawrence

When you are trying to improve the performance of a C program, there are many tools to "profile" your program - that is, to find out which parts of your program are slowing down the rest. Perl also has profilers - I wrote about one just yesterday (Perl Profiling with Devel::NYTProf). But what about shell scripts?

Yes, of course you can use the Unix "time" command. But that only tells you about the whole script - what if you want to track parts of it?

It's not that we expect blazing speed from shell scripts, of course. But still, there are times when we'd like to know how long some part of a script took to run.

Using "date"

In the olden days, we'd pick up the current time from "date" and store that. Then, after suspect part of the script, we'd run it again and calculate the elapsed time. Simple enough, but "date" limited us to whole seconds. We had nothing in the shell that was tighter than that.

Until GNU date, that is. GNU date added the %N flag, which handily displays nanoseconds. With that, we can write code like this:

#!/bin/bash
start=$(date +%s%N)
for c in {0..10}
do
..
..
..
done
new=$(date +%s%N)
elapsed=$((new - start))
echo $elapsed

A variation is to set PS4 to something that includes the time and run the script with "set -x".

Simple enough, right? Something like that might be exactly what you wanted, but there is another way.

Bash "time"

Bash has a built in "time" function. Most people know that, or would at least not be surprised to hear it. What you might not know is that "time" can be used within your shell scripts:

#!/bin/bash 
sleep=${1:-0}
echo sleep $sleep
time sleep $sleep
start=$(date +%s%N)
echo loop 10 times
time for c in {0..10}
do
 sleep $sleep
done
  
echo set \$new
time new=$(date +%s%N)

When run with "1" as an argument, this will produce something like:

sleep 1

real    0m1.003s
user    0m0.000s
sys     0m0.002s
loop 10 times

real    0m11.038s
user    0m0.013s
sys     0m0.023s
set $new

real    0m0.004s
user    0m0.000s
sys     0m0.003s

You can also run that with 0, which gives you some idea of the overhead of a bare loop.

sleep 0

real    0m0.003s
user    0m0.000s
sys     0m0.003s
loop 10 times

real    0m0.029s
user    0m0.008s
sys     0m0.017s
set $new

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

You might be curious as to the difference between ":" and "sleep 0":

#!/bin/bash 
sleep=${1:-0}
echo sleep $sleep
time sleep $sleep
start=$(date +%s%N)
echo loop 10 times
time for c in {0..10}
do
 :
done
  
echo set \$new
time new=$(date +%s%N)

That produced:

sleep 0

real    0m0.003s
user    0m0.000s
sys     0m0.002s
loop 10 times

real    0m0.000s
user    0m0.000s
sys     0m0.000s
set $new

real    0m0.003s
user    0m0.001s
sys     0m0.002s

So ":" is meaningless (within the limits of our precision, of course).

You can use "time" in front of functions and called pipelines as well. It isn't perhaps quite as handy as trapping the information in a variable, and the precision (which can be adjusted, see the man page) is limited to 3 digits, but it does tell the complete story.

times

Finally, you can sprinkle your script with "times" statements before or after certain sections.

#!/bin/bash 
sleep=${1:-0}
echo sleep $sleep
sleep $sleep
times
start=$(date +%s%N)
echo loop 10 times
for c in {0..10}
do
 :
done
times
  
echo set \$new
new=$(date +%s%N)
times

When run with "1" as its argument, you might get:

sleep 1
0m0.002s 0m0.003s
0m0.000s 0m0.002s
loop 10 times
0m0.003s 0m0.003s
0m0.002s 0m0.003s
set $new
0m0.003s 0m0.004s
0m0.003s 0m0.005s
 

Which is another way of looking at things.

Got something to add? Send me email.

---

Have you tried Searching this site?

This is a Unix/Linux resource website. It contains technical articles about Unix, Linux and general computing related subjects, opinion, news, help files, how-to's, tutorials and more.

Contact us