[dtrace-discuss] profile provider: is it me doing stupid things?

[Bryan Cantrill]

On Thu, Feb 15, 2007 at 04:49:45AM -0800, Paul van den Bogaard wrote:
> Just showing someone how great DTrace is and then we spot something I do not understand.
> Of course it can be a major misunderstanding of myself. Would appreciate another (expert) look upon this.
> 
> The goal we try to achieve is trying to get insight if there is a bursty nature in the time slot when system calls are done. Following DTrace snippet is tried:
> 
> dtrace -q -p 3173 -n 'syscall::read:entry  { @[probefunc] = count(); }  profile:::tick-250ms { printa("%6s %@6d\n", @); printf("\n"); clear(@); }'
> 
> This  to chop up a one second interval into four different equal sized 250 millsec slots. Counting the number of read and write syscalls that fall in each slot. 
> This one is run against a process that reads a single character and writes that character (stdin, stdout) continuously. Wrote it myself so I dare say it is functionally correct :-)
> 
> The output I get is:
> 
>   read  15078
>   read      0
>   read      0
>   read      0
> 
> And this pattern continues till hell freezes over: first slot has all the values, others are always zero. Tried this with 200msec and 100msec intervals too. No difference.
> 
> Mmmm I expect more of a uniform distribution. Lets try to sample in DTrace a little different. In the end it might be an unforeseen side effect of the application :)

It's actually a side-effect of both the switchrate and the aggrate.  The
switchrate dictates how frequently libdtrace(3LIB) reads the principal
buffer from dtrace(7D); the aggrate dictates how frequently the aggregation
buffers are read and processed.  Because your printa() both (1) emits data
to the principal buffer (to indicate that the printa() action should be
taken at user-level and (2) implicitly expects the aggregation to have
been updated at at least the same frequency, your script will only work
as you expect as long as your profile probe is of a lower frequency than
_both_ the switchrate _and_ the aggrate.  And, as you might have guessed
by now, both the switchrate and the aggrate default to 1hz.  

So:  to get your script to behave as you (rightly) expected, add this to
the command line:

   -x switchrate=250ms -x aggrate=250ms

While both the aggrate and the switchrate _are_ documented, their
interaction in a problem like this is quite subtle, and not explicitly
called out anywhere in the documentation; apologies for that...

	- Bryan

--------------------------------------------------------------------------
Bryan Cantrill, Solaris Kernel Development.       http://blogs.sun.com/bmc