1N/A**************************************************************************
1N/A* Notes for all scripts that print a function or method flow.
1N/A*
1N/A* $Id: ALLflow_notes.txt 44 2007-09-17 07:47:20Z brendan $
1N/A*
1N/A* COPYRIGHT: Copyright (c) 2007 Brendan Gregg.
1N/A**************************************************************************
1N/A
1N/A
1N/A* What is a flow?
1N/A
1N/AOutput that has some meaningful indent, such as function flow indented by
1N/Astack depth. eg,
1N/A
1N/A # ./pl_flow.d
1N/A C TIME(us) FILE -- SUB
1N/A 0 2963130861619 func_abc.pl -> func_a
1N/A 0 2963131870998 func_abc.pl -> func_b
1N/A 0 2963132871121 func_abc.pl -> func_c
1N/A 0 2963133881150 func_abc.pl <- func_c
1N/A 0 2963133881166 func_abc.pl <- func_b
1N/A 0 2963133881174 func_abc.pl <- func_a
1N/A ^C
1N/A
1N/A
1N/A* The output looks shuffled?
1N/A
1N/AEg,
1N/A
1N/A # ./pl_flow.d
1N/A C TIME(us) FILE -- SUB
1N/A 0 2963130861619 func_abc.pl -> func_a
1N/A 0 2963131870998 func_abc.pl -> func_b
1N/A 0 2963132871121 func_abc.pl -> func_c
1N/A 0 2963133881166 func_abc.pl <- func_b
1N/A 0 2963133881174 func_abc.pl <- func_a
1N/A 1 2963133881150 func_abc.pl <- func_c
1N/A ^C
1N/A
1N/AYes, this is shuffled. DTrace has been designed with a number of important
1N/Agoals in mind - including minimising the enabled performance overhead. To do
1N/Athis, per-CPU kernel buffers have been used to collect output, which are
1N/A(currently) dumped in sequence by /usr/sbin/dtrace whenever it wakes
1N/Aup ("switchrate" tunable). So, on multi-CPU servers, there is always the
1N/Apossibility that any DTrace script can print out-of-order data.
1N/A
1N/ATo deal with this behaviour, the flow scripts may,
1N/A
1N/A- print a "C" CPU column. If this changes from one line to the next then
1N/A the output is probably shuffled around that point. This is why the "C"
1N/A column appears in these flow scripts.
1N/A- print a "TIME(us)" column. You can eyeball this for shuffles, or just
1N/A post sort the dtrace output.
1N/A
1N/ANow have a closer look at the pl_flow.d output above. The change in C
1N/Aindicates that a shuffle may have happened, and the out-of-order TIME(us)
1N/Ashows that it did happen.
1N/A
1N/AIt is possible that DTrace will be enhanced to always sort output before
1N/Aprinting, and this behaviour is no longer an issue.
1N/A
1N/ASee "The output seems shuffled?" in Notes/ALLsnoop_notes.txt for more
1N/Anotes on this behaviour.
1N/A