ALLsnoop_notes.txt   [plain text]

The following are additional notes on ALL of the *snoop programs (such as
execsnoop, iosnoop, ..., and dapptrace, dtruss),


* The output seems shuffled?

Beware - due to the way DTrace works, on multi-CPU systems there is no
guarentee that if you print traced events the output is in the same order that
the events occured.

This is because events details are placed in per-CPU buffers, and then
combined by the DTrace consumer (/usr/sbin/dtrace) and printed out. The
DTrace consumer reads and prints the buffers one by one, it doesn't combine
them and sort them. 

To demonstrate this,

   # dtrace -n 'profile:::profile-3hz { trace(timestamp); }'
   dtrace: description 'profile-3hz ' matched 1 probe
   CPU     ID                    FUNCTION:NAME
     0  41241                     :profile-3hz  1898015274778547
     0  41241                     :profile-3hz  1898015608118262
     0  41241                     :profile-3hz  1898015941430060
     1  41241                     :profile-3hz  1898015275499014
     1  41241                     :profile-3hz  1898015609173485
     1  41241                     :profile-3hz  1898015942505828
     2  41241                     :profile-3hz  1898015275351257
     2  41241                     :profile-3hz  1898015609180861
     2  41241                     :profile-3hz  1898015942512708
     3  41241                     :profile-3hz  1898015274803528
     3  41241                     :profile-3hz  1898015608120522
     3  41241                     :profile-3hz  1898015941449884
   ^C

If you read the timestamps carefully, you'll see that they aren't quite
in chronological order. If you look at the CPU column while reading the
timestamps, the way DTrace works should become clear.

Most of the snoop tools have a switchrate of 10hz, so events may be shuffled
within a tenth of a second - not hugely noticable.

This isn't really a problem anyway. If you must have the output in the correct
order, find the switch that prints timestamps and then sort the output.
As an example,

   # iosnoop -t > out.iosnoop
   ^C
   # sort -n out.iosnoop
   
   TIME             UID   PID D    BLOCK   SIZE       COMM PATHNAME
   183710958520       0  3058 W 10507848   4096       sync /var/log/pool/poold
   183710990358       0  3058 W  6584858   1024       sync /etc/motd
   183711013469       0  3058 W    60655   9216       sync <none>
   183711020149       0  3058 W    60673   1024       sync <none>

All shell-wrapped scripts should have some way to print timestamps, if not
email me.