Wednesday, July 18, 2012

Tracing shell scripts with time stamps

A random tip for shell script hackers. You know that with set -x you can turn on tracing, so that every command is printed before being executed. In bash, you can also customize the output prefix by setting the PS4 variable. The default is PS4='+ '. Here is an example. I wanted to "profile" a deployment script, to see why it took so long. Ordinarily, I might have sprinkled it with date calls. Instead, I merely added
set -x
PS4='+\t '
near the top. \t stands for time stamp. (The script was already using bash explicitly, as opposed to /bin/sh.) That way, every line is prefixed by a time stamp, and the logs could easily be analyzed to find a possible performance bottleneck.


  1. Note that since Wheezy, (since bash 4.2) scripts can avoid forking to GNU/date, using the new string format based on strftime, of the shell built-in printf:

    $ printf '%(%Y/%m/%d %H:%M %S)T\n' -1
    2012/07/19 12:06 34

    Also note, that your tip will don't timestamp commands into functions. So in scripts with (long or complex) functions, it may be more convenient to use:

    set -xT

    Great tip, thanks for sharing!

  2. Forget what I said about functions, I was thinking in other profiling technique (using a trap on DEBUG).

    Your PS4 tip works flawlessly into functions.

  3. Thank's very much!! Work's like a charm!

  4. There's good amount of detail on logging for shell scripts via global varaibles of shell. We can emulate the similar kind of logging in shell script as shown here:

    The post has details on introducing log levels like INFO , DEBUG, ERROR. Tracing details like script entry, script exit, function entry, function exit.