dtrace discuss - Apr 2009 - Strange behavior of profile:::tick-10ms.

Hi, All,

For the following script, I hope the printed number should be sequential and
ordered. But the fact is not, anyone knows the reason or bug?


#!/usr/sbin/dtrace -s
#pragma D option quiet
BEGIN
{
   j=0;
}
profile:::tick-10ms
{
   i=1;
}
syscall:::
/i==1/
{
   i=0;
   j=j+1;
   printf("%d\n",j);
}


bash-3.00$ ./a.d            *  ===> I hope the ouptut is 1,2,3,4,5,.....
instead of 1,7,11,16 in a disordered way.*
1
5
13
14
18
38
47
48
57
58
63
74
2
3
.....
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<http://mail.opensolaris.org/pipermail/dtrace-discuss/attachments/20090417/bea0b4f9/attachment.html>

Hi,

Global variables are not thread-safe and ''j'' in your script is
a global
variable. This explains why you don''t see a list of numbers sorted in
ascending order.

Regards,
Krishnan

On Fri, 2009-04-17 at 18:03 +0800, Qihua Wu wrote:
> Hi, All,
> 
> For the following script, I hope the printed number should be
> sequential and ordered. But the fact is not, anyone knows the reason
> or bug?
> #!/usr/sbin/dtrace -s
> #pragma D option quiet
> BEGIN
> {
>    j=0;
> }
> profile:::tick-10ms
> {
>    i=1;
> }
> syscall:::
> /i==1/
> {
>    i=0;
>    j=j+1;
>    printf("%d\n",j);
> }
> 
> 
> bash-3.00$ ./a.d              ===> I hope the ouptut is
> 1,2,3,4,5,..... instead of 1,7,11,16 in a disordered way.
> 1
> 5
> 13
> 14
> 18
> 38
> 47
> 48
> 57
> 58
> 63
> 74
> 2
> 3
> .....
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org

On Fri, Apr 17, 2009 at 6:03 AM, Qihua Wu <dtrace.wu at gmail.com>
wrote:
> Hi, All,
>
> For the following script, I hope the printed number should be sequential
and
> ordered. But the fact is not, anyone knows the reason or bug?
>
>
> #!/usr/sbin/dtrace -s
> #pragma D option quiet
> BEGIN
> {
> ?? j=0;
> }
> profile:::tick-10ms
> {
> ?? i=1;
> }
> syscall:::
> /i==1/
> {
> ?? i=0;
> ?? j=j+1;
> ?? printf("%d\n",j);
> }
>
>
> bash-3.00$ ./a.d????????????? ===> I hope the ouptut is 1,2,3,4,5,.....
> instead of 1,7,11,16 in a disordered way.
This has to do with how the data are consumed.

Your D script increments j on the first system call in each 10-ms
interval.  The system happen on different CPUs.  The printf''s go into
a per-CPU buffer, and that buffer is going to be copied out to the
DTrace consumer (here dtrace(1M)) once per second.  (The rate is
tunable via switchrate.)

So on each CPU, you''ll have a buffer containing some random set of
numbers corresponding to the values j had when your syscall probe
fired and executed on that CPU.  Once a second, DTrace will walk the
CPUs and consume the buffer for each, and this is when the data get
printed.

Try changing the printf statement to the following:

   printf("%d %d\n",j, cpu);

You should see something like the following, where the CPU IDs are
grouped together (and possibly increasing within each one-second
interval, although I haven''t looked at the code to verify that that
will always be the case.)

7 0
11 0
12 0
13 0
23 0
33 0
34 0
35 0
36 0
44 0
45 0
47 0
53 0
54 0
59 0
72 0
74 0
78 0
2 1
6 1
9 1
16 2
20 2
21 2
22 2
40 2
42 3
43 3
47 3
80 3
88 3

Chad