Thursday, July 19, 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.