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:09 christos Exp $ 5* 6* COPYRIGHT: Copyright (c) 2007 Brendan Gregg. 7************************************************************************** 8 9 10* What is a flow? 11 12Output that has some meaningful indent, such as function flow indented by 13stack 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 28Eg, 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 40Yes, this is shuffled. DTrace has been designed with a number of important 41goals in mind - including minimising the enabled performance overhead. To do 42this, per-CPU kernel buffers have been used to collect output, which are 43(currently) dumped in sequence by /usr/sbin/dtrace whenever it wakes 44up ("switchrate" tunable). So, on multi-CPU servers, there is always the 45possibility that any DTrace script can print out-of-order data. 46 47To 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 55Now have a closer look at the pl_flow.d output above. The change in C 56indicates that a shuffle may have happened, and the out-of-order TIME(us) 57shows that it did happen. 58 59It is possible that DTrace will be enhanced to always sort output before 60printing, and this behaviour is no longer an issue. 61 62See "The output seems shuffled?" in Notes/ALLsnoop_notes.txt for more 63notes on this behaviour. 64 65