Home | History | Annotate | Line # | Download | only in Notes 
      1 **************************************************************************
      2 * Notes for all scripts that print a function or method flow.
      3 *
      4 * $Id: ALLflow_notes.txt,v 1.1.1.1 2015/09/30 22:01:08 christos Exp $
      5 *
      6 * COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
      7 **************************************************************************
      8 
      9 
     10 * What is a flow?
     11 
     12 Output that has some meaningful indent, such as function flow indented by
     13 stack depth. eg,
     14 
     15    # ./pl_flow.d 
     16      C TIME(us)          FILE             -- SUB
     17      0 2963130861619     func_abc.pl      -> func_a
     18      0 2963131870998     func_abc.pl        -> func_b
     19      0 2963132871121     func_abc.pl          -> func_c
     20      0 2963133881150     func_abc.pl          <- func_c
     21      0 2963133881166     func_abc.pl        <- func_b
     22      0 2963133881174     func_abc.pl      <- func_a
     23    ^C
     24 
     25 
     26 * The output looks shuffled?
     27 
     28 Eg,
     29 
     30    # ./pl_flow.d 
     31      C TIME(us)          FILE             -- SUB
     32      0 2963130861619     func_abc.pl      -> func_a
     33      0 2963131870998     func_abc.pl        -> func_b
     34      0 2963132871121     func_abc.pl          -> func_c
     35      0 2963133881166     func_abc.pl        <- func_b
     36      0 2963133881174     func_abc.pl      <- func_a
     37      1 2963133881150     func_abc.pl          <- func_c
     38    ^C
     39 
     40 Yes, this is shuffled. DTrace has been designed with a number of important
     41 goals in mind - including minimising the enabled performance overhead. To do
     42 this, per-CPU kernel buffers have been used to collect output, which are
     43 (currently) dumped in sequence by /usr/sbin/dtrace whenever it wakes
     44 up ("switchrate" tunable). So, on multi-CPU servers, there is always the
     45 possibility that any DTrace script can print out-of-order data.
     46 
     47 To deal with this behaviour, the flow scripts may,
     48 
     49 - print a "C" CPU column. If this changes from one line to the next then
     50   the output is probably shuffled around that point. This is why the "C"
     51   column appears in these flow scripts.
     52 - print a "TIME(us)" column. You can eyeball this for shuffles, or just
     53   post sort the dtrace output.
     54 
     55 Now have a closer look at the pl_flow.d output above. The change in C 
     56 indicates that a shuffle may have happened, and the out-of-order TIME(us)
     57 shows that it did happen.
     58 
     59 It is possible that DTrace will be enhanced to always sort output before
     60 printing, and this behaviour is no longer an issue.
     61 
     62 See "The output seems shuffled?" in Notes/ALLsnoop_notes.txt for more
     63 notes on this behaviour.
     64 
     65