LD_PRELOAD, or how I added timestamps to the output of anything.

A pet peeve of mine forever has been the fact that the \*stat family of tools don't timestamp their output. Oh sure, iostat has been granted a timestamp but vmstat, mpstat and the rest were left out in the cold. Yes, you could write a wrapper script which time stamps the beginning and the end of a ream of vmstat output but you still have to work to figure out when an event occurred in the middle of a 11,111,111 line capture of performance data.

Given my need to explore the odd nooks and crannies for what is possible, I thought it might be fun to write an LD_PRELOAD shared object which interjected a timestamp at the beginning of a line of output. All I'd need to do is provide a new printf and I'd be done right? Wrong!

After some messing about, it turned out that write(2) and _write() were the culprits that needed to be overridden to accomplish the mission. It also turned out that I needed to do some line buffering since I wanted the timestamp to be nice and tidy in column 1 of the output. For those of you with access to the internal network, you can find the fruit of my labor here. Those of you who don't can contact me and if my manager approves I could make it more widely available.

An example using venerable vmstat:

schwa:stamp-1.1 -> vmstat 1
 kthr      memory            page            disk          faults      cpu
 r b w   swap  free  re  mf pi po fr de sr f0 s0 s1 s6   in   sy   cs us sy id
 0 0 0 1729512 1154760 0 116 1  0  0  0  0  0  0  1  0  634 1594  717  1  1 97
 0 0 0 1648560 1030352 0 21  0  0  0  0  0  0  0  0  0  633 1323  466  0  0 100
 0 0 0 1648560 1030352 0 12  0  0  0  0  0  0  0  0  0  585 1157  425  0  0 100
 0 0 0 1648560 1030352 0 15  0  0  0  0  0  0  0 52  0  756 1143  492  0 21 79
 0 0 0 1648560 1030352 0 15  0  0  0  0  0  0  0  0  0  722 1658  509  0  0 100
\^C
schwa:stamp-1.1 -> setenv LD_PRELOAD stamp.so.1
schwa:stamp-1.1 -> vmstat 1
14:21:28  kthr      memory            page            disk          faults      cpu
14:21:28  r b w   swap  free  re  mf pi po fr de sr f0 s0 s1 s6   in   sy   cs us sy id
14:21:28  0 0 0 1729504 1154744 0 116 1  0  0  0  0  0  0  1  0  634 1594  717  1  1 97
14:21:29  0 0 0 1648480 1030272 0 23  0  0  0  0  0  0  0  0  0  591 1211  415  0  0 99
14:21:30  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  577 1179  413  0  1 99
14:21:31  0 0 0 1648480 1030272 0 12  0  0  0  0  0  0  0  0  0  582 1240  438  0  0 100
14:21:32  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  584 1150  404  0  0 100
14:21:33  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  644 1543  492  1  0 99
14:21:34  0 0 0 1648480 1030272 0 15  0  0  0  0  0  0  0  0  0  677 1353  477  0  0 100
14:21:35  0 0 0 1648480 1030272 0 18  0  0  0  0  0  0  0 27  0  843 1644  552  0  1 99
14:21:36  0 0 0 1647280 1030032 0 325 0  0  0  0  0  0  0  0  0  777 2056  687  8  0 92
14:21:37  0 0 0 1648480 1030272 0 16  0  0  0  0  0  0  0  0  0  705 1422  526  2  0 98
14:21:38  0 0 0 1648480 1030272 0 40  0  0  0  0  0  0  0  0  0  772 2260  723  3  0 97
\^C

Admittedly, not horribly clever but it scratched an itch.

-ejo

Comments:

Pretty cool!

Posted by manish on July 20, 2004 at 10:55 AM CDT #

Post a Comment:
Comments are closed for this entry.
About

ejo

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today
Bookmarks