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

[Paul van den Bogaard]

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 :)

The following DTrace script was used:

BEGIN
{
        baseline = timestamp;
}

syscall::read:entry
/pid == $target/
{
        this->tmp = (timestamp - baseline) / (1000 * 1000 * 250);
        @[this->tmp] = count();
}

profile:::tick-1000ms
{
        baseline = timestamp;
        printa("%3d  %@u\n", @);
        clear(@);
}

END
{
}

And this one does show a uniform distribution of the system calls as I expected:
  3  10601
  2  10610
  1  10940
  0  11534

Question: why is the profile:::tick-xxxmsec behaving this way? What am I missing?

Thanks
Paul
 
 
This message posted from opensolaris.org