cddl/contrib/dtracetoolkit/Notes/ALLsnoop_notes.txt

   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 44 2007-09-17 07:47:20Z brendan $
   6 *
   7 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
   8 **************************************************************************
   9
  10
  11 * The output seems shuffled?
  12
  13 Beware - due to the (current) way DTrace works, on multi-CPU systems there
  14 is no guarentee that if you print traced events the output is in the same
  15 order that the events occured.
  16
  17 This is because events details are placed in kernel per-CPU buffers, and then
  18 dumped in sequence by the DTrace consumer (/usr/sbin/dtrace) whenever it
  19 wakes up ("switchrate" tunable). The DTrace consumer reads and prints the
  20 buffers one by one, it doesn't combine them and sort them.
  21
  22 To 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
  41 If you read the timestamps carefully, you'll see that they aren't quite
  42 in chronological order. If you look at the CPU column while reading the
  43 timestamps, the way DTrace works should become clear.
  44
  45 Most of the snoop tools have a switchrate of 10hz, so events may be shuffled
  46 within a tenth of a second - not hugely noticable.
  47
  48 This isn't really a problem anyway. If you must have the output in the correct
  49 order, find the switch that prints timestamps and then sort the output.
  50 As 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
  62 All shell-wrapped scripts should have some way to print timestamps, and
  63 many DTrace-only scripts print timestamps by default. If you find a script
  64 that doesn't print timestamps, it should be trivial for you to add an
  65 extra column.
  66
  67 To add a microsecond-since-boot time column to a script, try adding this
  68 before every printf() you find,
  69
  70         printf("%-16d ", timestamp / 1000);
  71
  72 except for the header line, where you can add this,
  73
  74         printf("%-16s ", "TIME(us)");
  75
  76 Now you will be able to post sort the script output on the TIME(us) column.
  77
  78 In practise, I find post sorting the output a little annoying at times,
  79 and use a couple of other ways to prevent shuffling from happening in the
  80 first 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
  91 Another way to solve this problem would be to enhance DTrace to always print
  92 in-order output. Maybe this will be done one day; maybe by the time you
  93 are reading this it has already been done?
  94