Submit Hint Search The Forums LinksStatsPollsHeadlinesRSS
14,000 hints and counting!

Add timestamps to Unix commands that run at intervals UNIX
For a little project I was recently working on, I wanted to track some memory usage statistics over time. I figured that the Unix command vm_stat would be a good way to do that, as it includes the four basic memory usage types (free, active, inactive, and wired). My intent was to put this in a shell script that would run the command at a specified interval, dumping the output to a text file each time.

However, the basic output of vm_stat is less than ideal for dumping to a file via a shell script:
$ vm_stat
Mach Virtual Memory Statistics: (page size of 4096 bytes)
Pages free:                         486663.
Pages active:                       140886.
Pages inactive:                      92592.
Pages speculative:                  189887.
Pages wired down:                   138988.
"Translation faults":              1221453.
Pages copy-on-write:                 63521.
Pages zero filled:                  709169.
Pages reactivated:                       1.
Pageins:                             59295.
Pageouts:                                0.
Object cache: 28 hits of 34093 lookups (0% hit rate)
$
Parsing the above in a spreadsheet app would require some serious text manipulation. A brief glimpse at the man page for vm_stat showed another usage option: vm_stat interval, where interval is how often (in seconds) vm_stat should measure memory usage. When used in this way, the output is much nicer for capture:
$ vm_stat 2
Mach Virtual Memory Statistics: (page size of 4096 bytes, cache hits 0%)
  free active   spec inactive   wire   faults     copy    0fill reactive  pageins  pageout
486024 139635 191315    92771 138964  1224506    63581   711642        1    59301        0 
486194 139900 191372    92799 138445      392        0      366        0       10        0 
485056 139830 191381    93499 138966      100        0       36        0       42        0 
...
That was nearly perfect, though I only needed the first 36 characters (the end of the wire column). But I had a problem: I needed to include a timestamp on each row of the output, so I could tie memory usage back to some activities I was starting and stopping at specific times. Read on to see how this is done...

I didn't have the slightest idea how to add text to each row of output for a command that was running in a loop. For help, I turned to a guy who literally wrote the book on Perl, Randal Schwartz and who, coincidentally, also lives in the Portland area. (Odd aside: despite living within miles of each other, the first time I met Randal in person was in Florida for a Geek Cruise!).

After describing my desired output to Randal, he quickly sent back the following piece of Perl magic, which I'm not even going to attempt to decode. Instead, I'll just present it as "it works!," and it can be fairly easily used to attach a timestamp to any Unix program that creates output on a set interval. Here's the final version of Randal's solution:
vm_stat 2 | perl -lne '$| = 1; while (<STDIN>) { $z = localtime; substr($_,36) = ""; substr($_,0,0) = substr($z, 11, 8). ": "; print }'
Note that the above is designed to work with vm_stat output in 10.6; in 10.5, it's slightly different, and the substr($_,36) bit would need to have the 36 character count adjusted to match. The output of the above command is:
05:39:35:   free active   spec inactive   wire
05:39:35: 472838 139574 201659    95823 138999
05:39:37: 472468 139841 201660    95865 138959
05:39:39: 472443 139840 201661    95865 138958
05:39:41: 472213 139689 202127    95915 138940
...
That's exactly what needed. I added a >> /path/to/savefile.txt to dump the output to a text file, and had exactly what I needed. With some tweaking to the first substr command (which is what cuts the columns you want to see), this should work with most any command that generates continual output over time (though I've only tested it with vm_stat so far). Thanks Randal!
    •    
  • Currently 2.39 / 5
  You rated: 4 / 5 (18 votes cast)
 
[9,167 views]  

Add timestamps to Unix commands that run at intervals | 20 comments | Create New Account
Click here to return to the 'Add timestamps to Unix commands that run at intervals' hint
The following comments are owned by whoever posted them. This site is not responsible for what they say.
Add timestamps to Unix commands that run at intervals
Authored by: joem on Jan 22, '10 08:54:43AM
Or you could use the following, as it's easier to understand what's going on:
vm_stat 2 | gawk '{print strftime("%H:%M:%S:"), $1, $2, $3, $4}'

(note: this requires the GNU version of awk installed.)

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: joem on Jan 22, '10 08:58:27AM

Sorry, I should have mentioned that I wrote that on Leopard (in case it matters), and that you can pick and choose what columns you want by knowing that $1 is the first column, $2 is the second, and so on....



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: ctierney on Jan 22, '10 10:27:31AM
Hello,
If you don't have gawk, then you can try the following workaround:
vm_stat 2 | awk -v d=`date +%T:` '{print d, $1, $2, $3, $4}'


[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: kps on Jan 22, '10 11:07:16AM
That doesn't do the right thing; it prefixes every line with the time the command was started. Try
awk '{system("echo -n \"`date +%T` \""); print $0}'
Or using just the shell:
while read x; do echo "$(date +%T) $x"; done
More likely you'd make one of these a script, shell function, or alias, so that you could apply it easily to any output.

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: ctierney on Jan 23, '10 04:24:45AM

Oh! You're right. I was paying attention to my test output. Thanks.



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: Anonymous on Jan 22, '10 04:29:27PM
Retain the formatting with cut:
vm_stat 2 | cut -36 | sed "s/^/$(date --utc +%Y-%m-%dT%H:%M:%SZ:) /"
My usage of date also gives you UTC ISO timestamping for free...

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: mael on Jan 23, '10 04:56:26PM

hm...



~ $ vm_stat 2 | cut -36 | sed "s/^/$(date --utc +%Y-%m-%dT%H:%M:%SZ:) /"
cut: illegal option -- 3
usage: cut -b list [-n] [file ...]
cut -c list [file ...]
cut -f list [-s] [-d delim] [file ...]
date: illegal option -- -
usage: date [-jnu] [-d dst] [-r seconds] [-t west] [-v[+|-]val[ymwdHMS]] ...
[-f fmt date | [[[mm]dd]HH]MM[[cc]yy][.ss]] [+format]
w



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: Soliman on Jan 27, '10 05:26:23AM
Then just use cut -c 36 ;)

I still prefer the perl/awk version because fixing width at 36 is BADİ

---
Sylvain


[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: cabodj on Jan 22, '10 11:58:33AM

If your goal is to analyze the vmstat output over time, look for trends, etc, you could also install the free Mac version of Splunk. Once installed, look at the *nix app which has built-in collection and reporting on vmstat and many other *nix command-line tools. Behind the scenes, it's running vmstat, timestamping the output, parsing it, then presenting it to you in a nice interface.

Thought I'd throw that out there for anyone who didn't already have another destination in mind for their vmstat data.



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: Hal Itosis on Jan 22, '10 09:06:38PM
None of the above awk or sed worked right for me (in 10.5), and as for gawk, idunno... but sharing a script and telling users to install gawk is impractical and unnecessary. Regular old awk works fine for this:

vm_stat 2 |awk '{ system("printf '%-9s' `date +%T`"); print $1,$2,$3,$4 }'
23:58:38 Mach Virtual Memory Statistics:
23:58:38 free active inac wire
23:58:38 141575 130115 9608 44445
23:58:40 141539 130188 9608 44445
23:58:42 141547 130194 9608 44445
23:58:44 141511 130200 9608 44445
23:58:46 141412 130211 9608 44445

...or, add formatting all around for better spacing:

vm_stat 2 |awk '{ system("x=`date +%T`; printf '%-9s' $x"); 
printf("%9s %9s %9s %9s\n", $1,$2,$3,$4) }'
23:58:50      Mach   Virtual    Memory Statistics:
23:58:51      free    active      inac      wire
23:58:51    141067    130589      9608     44461
23:58:52    140916    130573      9608     44589
23:58:54    141037    130561      9608     44589
23:58:56    141019    130564      9608     44589
23:58:58    140967    130568      9608     44621

-HI-

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: slvrstn on Jan 22, '10 10:32:43PM
Getting back to a pure Perl solution, and I certainly don't want to get into a Perl golf match with Randal, but the whole substr approach is very specific to the formatting of vm_stat output, and as the OP pointed out, this changes between releases.

It can be accomplished more generally using the default autosplitting on whitespace:

vm_stat 2 | perl -ane 'printf "%.2d:%.2d:%.2d: @F[0..4]\n", (localtime())[2,1,0]'

Additional columns can be added by simply specifying more indices to the @F array, i.e., @F[0..4,6,9]

As in Hal's example, additional formatting can be added if desired:

vm_stat 2 | perl -ane 'printf "%.2d:%.2d:%.2d: %9s %9s %9s %9s\n", (localtime())[2,1,0], @F[0..4]'

This solution has the advantage over the awk (though not gawk) methods by not having to shell out to get the `date`

[ Reply to This | # ]

Add timestamps to Unix commands that run at intervals
Authored by: slvrstn on Jan 23, '10 06:15:10PM
Interesting, it previewed/looked fine under Firefox, but I see your issue under Safari. Lets hope this fixes it. My apologies.

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: Hal Itosis on Jan 22, '10 11:18:59PM
(NOTE: this message probably appears in "code" due to a missing code tag in the previous post by slvrstn ?!)
Rats!!!... in a flurry of copy/paste editing from Terminal, i accidently posted an older version for the second example. (i.e., no need for the x= variable assignment... that part of example 2 should look just like example 1). I.e.,

vm_stat 2 |awk '{ system("printf '%-9s' `date +%T`"); 
printf("%9s %9s %9s %9s\n", $1,$2,$3,$4) }'
Edited on Jan 22, '10 11:25:07PM by Hal Itosis


[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: bashbash on Jan 23, '10 01:00:07AM
Some of the above scripts do not work for me, and I'm not sure why you need awk or perl at all.

This simple script also strips the vm_stat headers and formats the output.

vm_stat 2|while read l;do [[ ! $l =~ [A-z] ]]&&echo $(date +%H:%M:%S) ${l:0:36};done


[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: Hal Itosis on Jan 23, '10 10:34:22AM

@ bashbash:

>> I'm not sure why you need awk or perl at all.

Because... awking 4 fields will work no matter what their combined width is. Fixating on a 36-char width only works for versions of vm_stat which produce that particular output. As stated in the article, the outputs from 10.5. and 10.6 have slight differences, and who knows if 10.7 will stay with 36-chars? Working with *fields* instead of specific widths obviates all that incompatibility and uncertainty.


>> This simple script also strips the vm_stat headers and formats the output.

Stripping the headers may be nice (or maybe not), but those numbers in the columns are printed out *left*-justified... which is not exactly a desirable "format". ;-)

--

PS: could some mod/admin please cleanup the code tag problem? I think slvrstn's post is missing a closing code tag.



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: bashbash on Jan 24, '10 05:46:53AM
Many apologies, I should have explained my script.

If you don't want to filter out the headers, don't apply the filter:

vm_stat 2|while read l;do echo $(date +%H:%M:%S) ${l:0:36};done

If you want to retain the original formatting, pop in some quotes:

vm_stat 2|while read l;do [[ ! $l =~ [A-z] ]]&&echo $(date +%H:%M:%S) "${l:0:36}";done

If you want to use positional parameters and printfs use something like this:

vm_stat 2|while read a b c d e;do printf "%s %9s %9s %9s %9s %9s\n" $(date +%T) $a $b $c $d;done

That one mimics the previous awk script.

I thought the OP wanted something that was easily machine readable. In that case maybe something like this would do the trick:

vm_stat 2|while read a b c d e;do [[ ! $a =~ [A-z] ]]&&echo $(date +%T) $a $b $c $d;done

In all cases, bash has plenty of builtin formatting without resorting to language soup :)

I have a great fondness for other languages (especially awk), but let's not perpetuate the myth that bash cannot do these things just as easily. There is also an overhead of invoking extra interpreters.

[ Reply to This | # ]

Add timestamps to Unix commands that run at intervals
Authored by: slvrstn on Jan 24, '10 01:32:13PM
OK, let's look at this extra overhead issue, because it's exactly what I was talking about in my original post when I mentioned the advantage of not shelling out to get the timestamp.

To benchmark, we want to generate a lot of data quickly, so I used

time od -N 1000000 -D /dev/random | wc
   62501  312501 4625008

real	0m0.310s
user	0m0.170s
sys	0m0.153s

to generate around 62k lines of the form

0000000         455208253      2432249641      1505621869      3979473917
0000020        2293418554      1733714563      3308048974       965145382
0000040        2395066143      3983717352      2757720288      3811753968
...

You see that it takes less than half a second to generate the data.

Then, comparing methodologies:

Perl

time od -N 1000000 -D /dev/random | perl -ane 'printf "%.2d:%.2d:%.2d: @F[0..4]\n", (localtime())[2,1,0]'  > /dev/null

real	0m0.869s
user	0m0.813s
sys	0m0.162s

bash

time od -N 1000000 -D /dev/random | while read a b c d e;do printf "%s %9s %9s %9s %9s %9s\n" $(date +%T) $a $b $c $d;done  > /dev/null

real	3m43.331s
user	0m52.922s
sys	2m27.505s

So, it takes less than a second with the pure Perl and over 3 1/2 minutes in pure bash.

Any approach that has to invoke a new command to get the timestamp each time through the loop is going to suffer by the same comparison.

[ Reply to This | # ]

Add timestamps to Unix commands that run at intervals
Authored by: Hal Itosis on Jan 24, '10 03:17:47PM
Holy Moly Perl-man... point well made, and taken. 8-)

How is it that Perl manages to get the current timestamp
for each iteration so much _more_ quickly? Doesn't it need
to request that info (in real time) from the OS as well?
[it also seems to parse the data strings faster too]

Anyway, thanks for that impressive proof.

[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: slvrstn on Jan 24, '10 09:07:11PM

In the end, both perl and the `date` command are making the same system library call, time.
See `man -s 3 time`

The difference is all in the overhead in setting up the execution environment.
In the perl, this is done once and the interpreter can then make rapid-fire system calls.
In the bash (and awk) examples, every invocation of `date` has to exec a full new command / execution environment, which is comparatively extremely resource intensive.

bash is a fantastic and very capable shell, but unless your script is written entirely with built-ins, you are going to pay a performance penalty for every external command invoked. This isn't something exclusive to bash, of course. You have the same issues in Perl, in fact, if your script relies heavily on using the system, exec, or backtick commands.



[ Reply to This | # ]
Add timestamps to Unix commands that run at intervals
Authored by: bashbash on Jan 25, '10 12:28:53AM

Wow!

May I humbly suggest to give C a go. You never know, it might give perl a run for its money? (just joking)

Also, if you really do want to compare the overheads of perl and date, you might need a different benchmark: I was under the impression that "benchmarks" generally try to achieve the same result with the same algorithm. I could be wrong there too though.

In future, I'll just recommend people become perl wizards rather helping them expand their knowledge . That's worked well for everyone so far.



[ Reply to This | # ]