View source for Timestamp

=Generating Timestamps=

I've run into compiled code (no source available) that did not timestamp debugging output. This created problems for troubleshooting. What's a mother to do? We're looking to do something like this:

<pre>
progam_being_debugged 2>&1 | timestamp_generator > badapp.log
</pre>

There are many ways to do this, "this" being "program_being_debugged".

Here are the methods explored below:

*shell
*awk
*daemontools  (tai64n[local])
*ts (from moreutils; see "moreutils" page on this wiki)
*perl

Of course there are some other ways to do this: write a 'C' program (don't know if 'ts' is written in C or something else), try various other languages. However, the scope of this project was "quick & dirty" with the emphasis on quick. Nonetheless, I managed to carve out the time necessary to test the methods above.

Note that when debugging, we often want to 'tail' the output to watch what's going on in realtime, and possibly use our monkey minds to attempt to correlate with external events. Like so:

<pre>
program_being_debugged 2>&1 | timestamp_generator | tail -f
</pre>

In this case, it's important to minimize buffering along the pipeline so that output gets to our optical sensors as quickly as possible. This can be done with the "unbuffer" command, which requires installation of the 'expect' package (expect-dev on some distros).

==Results==

A simple shell script harness was used for the testing:

<pre>
example
</pre>

Summary:

Perhaps surprisingly, the awk and perl versions performed the best. The difference between the perl and awk versions were slight. The perl version, at most, used 10% more memory and resources than the awk version. Very impressive for the "kitchen sink" language.

The tests were performed on a machine under Ubuntu 14.10. Here are the results:







===shell===
bash version
<pre>
  188.36   user
  779.17   system
13:25.67   elapsed
    120%   CPU
(0avgtext+0avgdata 6072maxresident)k
0inputs+0outputs
(0major+28033858minor)pagefaults
0          swaps
</pre>

===awk===
awk version
<pre>
   6.49    user
  12.23    system
0:12.42    elapsed
  150 %    CPU
(0avgtext+0avgdata 6072maxresident)k
0inputs+0outputs pagefaults
      0    swaps
</pre>

===daemontools===

daemontools
<pre>
   6.03    user
  17.68    system
0:13.12    elapsed 180%CPU (0avgtext+0avgdata 6080maxresident)k
0inputs+0outputs 
(0major+139066minor)pagefaults
0swaps
</pre>

===ts===
ts version
<pre>
  16.81   user
  14.19   system
0:16.22   elapsed
    191   %CPU
(0avgtext+0avgdata 7864maxresident)k
0inputs+0outputs 
(0major+210354minor)pagefaults
0         swaps
</pre>

===perl===

perl
<pre>
  6.78    user
 11.80    system
0:12.20   elapsed
   152%   CPU
(0avgtext+0avgdata 7868maxresident)k
0inputs+0outputs 
0major+141587minor)pagefaults
0swaps
</pre>

==Random==

===Shell History===

Shell History Timestamping

HISTTIMEFORMAT takes format string of strftime. Check out the strftime manual to choose and construct the timestamp that suit your taste. My favorite is “%F %T “.
export HISTTIMEFORMAT="%F %T "

Execute history again and you will see the effect on the spot, bare in mind that the timestamp for command lines that executed at previous sessions may not valid, as the time was not tracked.