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