1The following are additional notes on ALL of the *snoop programs (such as
2execsnoop, iosnoop, ..., and dapptrace, dtruss),
3
4
5* The output seems shuffled?
6
7Beware - due to the way DTrace works, on multi-CPU systems there is no
8guarentee that if you print traced events the output is in the same order that
9the events occured.
10
11This is because events details are placed in per-CPU buffers, and then
12combined by the DTrace consumer (/usr/sbin/dtrace) and printed out. The
13DTrace consumer reads and prints the buffers one by one, it doesn't combine
14them and sort them. 
15
16To demonstrate this,
17
18   # dtrace -n 'profile:::profile-3hz { trace(timestamp); }'
19   dtrace: description 'profile-3hz ' matched 1 probe
20   CPU     ID                    FUNCTION:NAME
21     0  41241                     :profile-3hz  1898015274778547
22     0  41241                     :profile-3hz  1898015608118262
23     0  41241                     :profile-3hz  1898015941430060
24     1  41241                     :profile-3hz  1898015275499014
25     1  41241                     :profile-3hz  1898015609173485
26     1  41241                     :profile-3hz  1898015942505828
27     2  41241                     :profile-3hz  1898015275351257
28     2  41241                     :profile-3hz  1898015609180861
29     2  41241                     :profile-3hz  1898015942512708
30     3  41241                     :profile-3hz  1898015274803528
31     3  41241                     :profile-3hz  1898015608120522
32     3  41241                     :profile-3hz  1898015941449884
33   ^C
34
35If you read the timestamps carefully, you'll see that they aren't quite
36in chronological order. If you look at the CPU column while reading the
37timestamps, the way DTrace works should become clear.
38
39Most of the snoop tools have a switchrate of 10hz, so events may be shuffled
40within a tenth of a second - not hugely noticable.
41
42This isn't really a problem anyway. If you must have the output in the correct
43order, find the switch that prints timestamps and then sort the output.
44As an example,
45
46   # iosnoop -t > out.iosnoop
47   ^C
48   # sort -n out.iosnoop
49   
50   TIME             UID   PID D    BLOCK   SIZE       COMM PATHNAME
51   183710958520       0  3058 W 10507848   4096       sync /var/log/pool/poold
52   183710990358       0  3058 W  6584858   1024       sync /etc/motd
53   183711013469       0  3058 W    60655   9216       sync <none>
54   183711020149       0  3058 W    60673   1024       sync <none>
55
56All shell-wrapped scripts should have some way to print timestamps, if not
57email me.
58
59