How To Add a Timestamp to Each Line of Output on Linux

For performance monitoring on linux, you typically would like your shell script metrics and statistics that are logged periodically to include the timestamp with each line output.  That way, the information can later be correlated with other system events such as event log entries or system errors.  There are two basic scenarios.

1. Your shell script is echoing information to standard output periodically in some loop
2. You are just calling a program such as vmstat directly that outputs information periodically

Adding a timestamp in the two scenarios can be handled easily as follows:

Monitoring Loop

If your monitoring script includes a loop that is outputting stats periodically, a timestamp can be added to each line by capturing the output of the "date" command and then adding that information to the output line.

The output of the date command can be captured by using forward single quotes, as follows:

savedDate = `date`

Here is an example of a script making use of this technique:

#

# output stats every $1 seconds until stopped

#

if [ "$1" == "" ] ; then

  echo "syntax= .stats.sh <intervalSeconds>"

  exit

fi

time=$1

echo "Time , QueriesPerSechod" > mysql-stats.log

while :

do

    qps=`mysql -u mysql -e "show status" | awk '{if ($1 == "Queries") print $2}'`

    date=`date`

    echo "$date , $qps" >> mysql-stats.log

    sleep $time

done

Here is an example of the output:

Time , QueriesPerSecond

Wed Aug  8 16:11:58 PDT 2012 , 3029

Wed Aug  8 16:12:08 PDT 2012 , 18195 

Wed Aug  8 16:12:18 PDT 2012 , 18903

...

Direct Output

If you are just calling an app or script such as vmstat, iostat, etc., that outputs stats periodically for you, you can achieve the same effect by piping the command through an app that prepends a timestamp to each line.  For example, to prepend timestamps to the output from vmstat, free, and iostat, you would do the following, depending on a script "timestamp.sh" with the timestamp prepend behavior:

# free

free -g -s 10 | ./timestamp.sh > free.log &

# vmstat

vmstat 10 | ./timestamp.sh > vmstat.log &

# iostat

iostat 10 | ./timestamp.sh > iostat.log &

This would give output such as the following:

07/23/12 10:41:44,procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

07/23/12 10:41:44, r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

07/23/12 10:41:44, 6  0   2736 3381052 505844 159601296    0    0    62   119    1    1  6  1 93  0  0

07/23/12 10:41:54, 2  0   2736 3358836 505900 159601728    0    0   102    25  640  414  1  0 99  0  0

07/23/12 10:42:04, 7  0   2736 3329736 505948 159601936    0    0     9    32  927 1263  1  0 98  0  0

The timestamp.sh script is as follows:

#!/usr/bin/perl

#while (<>) { print localtime() . ": $_"; }

while (<>) 

{

($sec,$min,$hour,$mday,$mon,$year,$wday,$yday,$isdst) = localtime(time);

$secpad = sprintf( "%02d", $sec );

$minpad = sprintf( "%02d", $min );

$hourpad = sprintf( "%02d", $hour );

$monpad = sprintf( "%02d", $mon );

$mdaypad = sprintf( "%02d", $mday );

$yearpad = sprintf( "%02d", ($year + 1900) % 100 );

$time = "$monpad\/$mdaypad\/$yearpad $hourpad:$minpad:$secpad";

print $time . ",$_" ;

#17/04/112 16:40:14

}