1************************************************************************** 2* The following are additional notes on ALL of the *snoop programs (such as 3* execsnoop, iosnoop, ..., and dapptrace, dtruss). 4* 5* $Id: ALLsnoop_notes.txt,v 1.1.1.1 2015/09/30 22:01:08 christos Exp $ 6* 7* COPYRIGHT: Copyright (c) 2007 Brendan Gregg. 8************************************************************************** 9 10 11* The output seems shuffled? 12 13Beware - due to the (current) way DTrace works, on multi-CPU systems there 14is no guarentee that if you print traced events the output is in the same 15order that the events occured. 16 17This is because events details are placed in kernel per-CPU buffers, and then 18dumped in sequence by the DTrace consumer (/usr/sbin/dtrace) whenever it 19wakes up ("switchrate" tunable). The DTrace consumer reads and prints the 20buffers one by one, it doesn't combine them and sort them. 21 22To demonstrate this, 23 24 # dtrace -n 'profile:::profile-3hz { trace(timestamp); }' 25 dtrace: description 'profile-3hz ' matched 1 probe 26 CPU ID FUNCTION:NAME 27 0 41241 :profile-3hz 1898015274778547 28 0 41241 :profile-3hz 1898015608118262 29 0 41241 :profile-3hz 1898015941430060 30 1 41241 :profile-3hz 1898015275499014 31 1 41241 :profile-3hz 1898015609173485 32 1 41241 :profile-3hz 1898015942505828 33 2 41241 :profile-3hz 1898015275351257 34 2 41241 :profile-3hz 1898015609180861 35 2 41241 :profile-3hz 1898015942512708 36 3 41241 :profile-3hz 1898015274803528 37 3 41241 :profile-3hz 1898015608120522 38 3 41241 :profile-3hz 1898015941449884 39 ^C 40 41If you read the timestamps carefully, you'll see that they aren't quite 42in chronological order. If you look at the CPU column while reading the 43timestamps, the way DTrace works should become clear. 44 45Most of the snoop tools have a switchrate of 10hz, so events may be shuffled 46within a tenth of a second - not hugely noticable. 47 48This isn't really a problem anyway. If you must have the output in the correct 49order, find the switch that prints timestamps and then sort the output. 50As an example, 51 52 # iosnoop -t > out.iosnoop 53 ^C 54 # sort -n out.iosnoop 55 56 TIME UID PID D BLOCK SIZE COMM PATHNAME 57 183710958520 0 3058 W 10507848 4096 sync /var/log/pool/poold 58 183710990358 0 3058 W 6584858 1024 sync /etc/motd 59 183711013469 0 3058 W 60655 9216 sync <none> 60 183711020149 0 3058 W 60673 1024 sync <none> 61 62All shell-wrapped scripts should have some way to print timestamps, and 63many DTrace-only scripts print timestamps by default. If you find a script 64that doesn't print timestamps, it should be trivial for you to add an 65extra column. 66 67To add a microsecond-since-boot time column to a script, try adding this 68before every printf() you find, 69 70 printf("%-16d ", timestamp / 1000); 71 72except for the header line, where you can add this, 73 74 printf("%-16s ", "TIME(us)"); 75 76Now you will be able to post sort the script output on the TIME(us) column. 77 78In practise, I find post sorting the output a little annoying at times, 79and use a couple of other ways to prevent shuffling from happening in the 80first place: 81 82- offline all CPUs but one when running flow scripts. Naturally, you 83 probably don't want to do this on production servers, this is a trick 84 that may be handy for when developing on workstations or laptops. Bear 85 in mind that if you are trying to DTrace certain issues, such as 86 multi-thread locking contention, then offlining most CPUs may eliminate 87 the issue you are trying to observe. 88- pbind the target process of interest to a single CPU. Most OSes provide 89 a way to glue a process to a single CPU; Solaris has both pbind and psrset. 90 91Another way to solve this problem would be to enhance DTrace to always print 92in-order output. Maybe this will be done one day; maybe by the time you 93are reading this it has already been done? 94 95