dtrace discuss - Sep 2006 - Unconventional sampling - fire probe 1 in n times?

I''m trying to analyse the performance of some low-level threading code
using dtrace. In particular I want to capture ''time in queue''
for items, which I''m doing something like this:

[b]foo$target:::enqueue
{
	entrytimes[arg0] = timestamp; [i]# arg0 is the pointer being queued[/i]
}

foo$target:::dequeue
{
	@latency = quantize(timestamp - entrytimes[arg0]);
	entrytimes[arg0] = 0;
}[/b]

This works fine, but it is far too slow (I''m doing 10K+ enqueue/dequeue
pairs a second in my test harness). What I''d like to do is pick only a
sample of the enqueue/dequeue pairs to perform timing on, but I can''t
figure out how, I thought I might be able to predicate on ''count() %
n'' but dtrace doesn''t like this:

[b]foo$target:::enqueue
/ count() % 100 == 0 /
{
    ...[/b]

giving an error:

[i]dtrace: failed to compile script test.d: line 4: operator % requires operands
of integral type[/i]

Any other suggestions (I don''t think ''conventional''
sampling can do the trick because I need to pick pairs of enqueue/dequeue
operations which do not occur in the same thread...)?

Thanks,

Matt.
 
 
This message posted from opensolaris.org

Matt,

How about:

    /self->n++ % 100 == 0/

Regards,
Tim

Matt Stupple wrote:
> I''m trying to analyse the performance of some low-level threading
code using dtrace. In particular I want to capture ''time in
queue'' for items, which I''m doing something like this:
>
> [b]foo$target:::enqueue
> {
> 	entrytimes[arg0] = timestamp; [i]# arg0 is the pointer being queued[/i]
> }
>
> foo$target:::dequeue
> {
> 	@latency = quantize(timestamp - entrytimes[arg0]);
> 	entrytimes[arg0] = 0;
> }[/b]
>
> This works fine, but it is far too slow (I''m doing 10K+
enqueue/dequeue pairs a second in my test harness). What I''d like to do
is pick only a sample of the enqueue/dequeue pairs to perform timing on, but I
can''t figure out how, I thought I might be able to predicate on
''count() % n'' but dtrace doesn''t like this:
>
> [b]foo$target:::enqueue
> / count() % 100 == 0 /
> {
>     ...[/b]
>
> giving an error:
>
> [i]dtrace: failed to compile script test.d: line 4: operator % requires
operands of integral type[/i]
>
> Any other suggestions (I don''t think
''conventional'' sampling can do the trick because I need to
pick pairs of enqueue/dequeue operations which do not occur in the same
thread...)?
>
> Thanks,
>
> Matt.
>  
>  
> This message posted from opensolaris.org
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>   
-- 
Tim Cook
Performance, Availability and Architecture Engineering
<> Sun Microsystems
Ph:     +1 650 257 4709
Ext:	(70) 69841

Or you could use the rand() function to perform stochastic sampling.

Adam

On Tue, Sep 19, 2006 at 10:26:37AM -0700, Tim Cook - PAE
wrote:
> Matt,
> 
> How about:
> 
>    /self->n++ % 100 == 0/
> 
> Regards,
> Tim
> 
> Matt Stupple wrote:
> >I''m trying to analyse the performance of some low-level
threading code
> >using dtrace. In particular I want to capture ''time in
queue'' for items,
> >which I''m doing something like this:
> >
> >[b]foo$target:::enqueue
> >{
> >	entrytimes[arg0] = timestamp; [i]# arg0 is the pointer being 
> >	queued[/i]
> >}
> >
> >foo$target:::dequeue
> >{
> >	@latency = quantize(timestamp - entrytimes[arg0]);
> >	entrytimes[arg0] = 0;
> >}[/b]
> >
> >This works fine, but it is far too slow (I''m doing 10K+
enqueue/dequeue
> >pairs a second in my test harness). What I''d like to do is
pick only a
> >sample of the enqueue/dequeue pairs to perform timing on, but I
can''t
> >figure out how, I thought I might be able to predicate on
''count() % n''
> >but dtrace doesn''t like this:
> >
> >[b]foo$target:::enqueue
> >/ count() % 100 == 0 /
> >{
> >    ...[/b]
> >
> >giving an error:
> >
> >[i]dtrace: failed to compile script test.d: line 4: operator % requires
> >operands of integral type[/i]
> >
> >Any other suggestions (I don''t think
''conventional'' sampling can do the
> >trick because I need to pick pairs of enqueue/dequeue operations which
do
> >not occur in the same thread...)?
> >
> >Thanks,
> >
> >Matt.
> > 
> > 
> >This message posted from opensolaris.org
> >_______________________________________________
> >dtrace-discuss mailing list
> >dtrace-discuss at opensolaris.org
> >  
> 
> -- 
> Tim Cook
> Performance, Availability and Architecture Engineering
> <> Sun Microsystems
> Ph:     +1 650 257 4709
> Ext:	(70) 69841
> 
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
-- 
Adam Leventhal, Solaris Kernel Development       http://blogs.sun.com/ahl

Gotta be careful with that, though:

Bug ID: 5029696 Synopsis: dtrace rand function not random

Adam Leventhal wrote:
> Or you could use the rand() function to perform stochastic sampling.
> 
> Adam
> 
> On Tue, Sep 19, 2006 at 10:26:37AM -0700, Tim Cook - PAE wrote:
>> Matt,
>>
>> How about:
>>
>>    /self->n++ % 100 == 0/
>>
>> Regards,
>> Tim
>>
>> Matt Stupple wrote:
>>> I''m trying to analyse the performance of some low-level
threading code
>>> using dtrace. In particular I want to capture ''time in
queue'' for items,
>>> which I''m doing something like this:
>>>
>>> [b]foo$target:::enqueue
>>> {
>>> 	entrytimes[arg0] = timestamp; [i]# arg0 is the pointer being 
>>> 	queued[/i]
>>> }
>>>
>>> foo$target:::dequeue
>>> {
>>> 	@latency = quantize(timestamp - entrytimes[arg0]);
>>> 	entrytimes[arg0] = 0;
>>> }[/b]
>>>
>>> This works fine, but it is far too slow (I''m doing 10K+
enqueue/dequeue
>>> pairs a second in my test harness). What I''d like to do is
pick only a
>>> sample of the enqueue/dequeue pairs to perform timing on, but I
can''t
>>> figure out how, I thought I might be able to predicate on
''count() % n''
>>> but dtrace doesn''t like this:
>>>
>>> [b]foo$target:::enqueue
>>> / count() % 100 == 0 /
>>> {
>>>    ...[/b]
>>>
>>> giving an error:
>>>
>>> [i]dtrace: failed to compile script test.d: line 4: operator %
requires
>>> operands of integral type[/i]
>>>
>>> Any other suggestions (I don''t think
''conventional'' sampling can do the
>>> trick because I need to pick pairs of enqueue/dequeue operations
which do
>>> not occur in the same thread...)?
>>>
>>> Thanks,
>>>
>>> Matt.
>>>
>>>
>>> This message posted from opensolaris.org
>>> _______________________________________________
>>> dtrace-discuss mailing list
>>> dtrace-discuss at opensolaris.org
>>>  
>> -- 
>> Tim Cook
>> Performance, Availability and Architecture Engineering
>> <> Sun Microsystems
>> Ph:     +1 650 257 4709
>> Ext:	(70) 69841
>>
>> _______________________________________________
>> dtrace-discuss mailing list
>> dtrace-discuss at opensolaris.org
> 

-- 
blu

"When I was a boy I was told that anybody could become
President; I''m beginning to believe it." - Clarence Darrow
----------------------------------------------------------------------
Brian Utterback - OP/N1 RPE, Sun Microsystems, Inc.
Ph:877-259-7345, Em:brian.utterback-at-ess-you-enn-dot-kom

Doh! Seems so obvious now you say it...

Thanks.
 
 
This message posted from opensolaris.org

> Or you could use the rand() function to perform
> stochastic sampling.
> 
I''d like to try this, but am I doing it wrong? When I write something
like this in a script:

foo:::enqueue
/ rand() % 101 == 0 /
{
    ...

then the action just never fires. (Using 101 just because it seems
''right'' to use a prime here...?) Even if I predicate on rand()
% 3 - in a test where the enqueue operation is invoked a million times - it
never fires.

If I remove the predicate, and ask quantize to collect the results of rand() %
101 for me:

foo:::enqueue
{
    ...
    @randoms = quantize(rand() % 101);
}

then I get a ''correct looking'' distribution:

           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |                                         965      
               1 |                                         955      
               2 |@                                        1939     
               4 |@@                                       3798     
               8 |@@@                                      7909     
              16 |@@@@@@                                   15507    
              32 |@@@@@@@@@@@@@                            32062    
              64 |@@@@@@@@@@@@@@@                          36865    
             128 |                                         0        

so, I assume that I''m writing my predicate wrong ... or something else
strange is happening.

Thanks (again!)

Matt.
 
 
This message posted from opensolaris.org

Matt,

Your predicate looks right.  I ran the following:

BEGIN
{
   i = 0;
}
tick-100
{
   i++;
}
tick-100
/ rand() % 101 == 0 /
{
   trace (i);
   @["Average"] = avg(i);
   i = 0;
}

and got these results:

dtrace: script ''rcount.d'' matched 3 probes
CPU     ID                    FUNCTION:NAME
  0   1462                        :tick-100        83
  0   1462                        :tick-100       195
  0   1462                        :tick-100       140
  0   1462                        :tick-100       139
  0   1462                        :tick-100       129
  0   1462                        :tick-100       162
  0   1462                        :tick-100       106
  0   1462                        :tick-100        89
  0   1462                        :tick-100       218
  0   1462                        :tick-100       179
  0   1462                        :tick-100       101
  0   1462                        :tick-100        28
  0   1462                        :tick-100         6
  0   1462                        :tick-100         5
  0   1462                        :tick-100       269
  0   1462                        :tick-100       217
^C

  Average                                                         129

Are you sure the "enqueue" probe is firing?

Chip

Matt Stupple wrote:
>> Or you could use the rand() function to perform
>> stochastic sampling.
>>
>>     
>
> I''d like to try this, but am I doing it wrong? When I write
something like this in a script:
>
> foo:::enqueue
> / rand() % 101 == 0 /
> {
>     ...
>
> then the action just never fires. (Using 101 just because it seems
''right'' to use a prime here...?) Even if I predicate on rand()
% 3 - in a test where the enqueue operation is invoked a million times - it
never fires.
>
> If I remove the predicate, and ask quantize to collect the results of
rand() % 101 for me:
>
> foo:::enqueue
> {
>     ...
>     @randoms = quantize(rand() % 101);
> }
>
> then I get a ''correct looking'' distribution:
>
>            value  ------------- Distribution ------------- count    
>               -1 |                                         0        
>                0 |                                         965      
>                1 |                                         955      
>                2 |@                                        1939     
>                4 |@@                                       3798     
>                8 |@@@                                      7909     
>               16 |@@@@@@                                   15507    
>               32 |@@@@@@@@@@@@@                            32062    
>               64 |@@@@@@@@@@@@@@@                          36865    
>              128 |                                         0        
>
> so, I assume that I''m writing my predicate wrong ... or something
else strange is happening.
>
> Thanks (again!)
>
> Matt.
>  
>  
> This message posted from opensolaris.org
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>

I''m *not* sure the enqueue probe is firing - but I don''t
understand why it wouldn''t be.

To be specific here''s my real .d script:

fwtools$target:::workpool-enqueue
/ rand() % 101 == 0 /
{
	entrytimes[arg1] = timestamp;
}

/*
fwtools$target:::workpool-enqueue
{
	@["random"] = quantize(rand() % 101)
}
*/

fwtools$target:::workpool-dequeue
/ entrytimes[arg1] > 0 /
{
	@["latency"] = quantize(timestamp - entrytimes[arg1]);
	entrytimes[arg1] = 0;
}

Which I run like this (the parameters to the testwpool_performance binary
aren''t relevant to this discussion):

$ dtrace -s testpool.d -c ''testwpool_performance 10 2 100000''

... and get this output ...

dtrace: script ''testpool.d'' matched 2 probes
dtrace: pid 7681 has exited

However, if I uncomment the second action block in my script then I get this
instead:

dtrace: script ''testpool.d'' matched 2 probes
dtrace: pid 7712 has exited

  random                                            
           value  ------------- Distribution ------------- count    
              -1 |                                         0        
               0 |                                         910      
               1 |                                         975      
               2 |@                                        1988     
               4 |@@                                       3936     
               8 |@@@                                      7934     
              16 |@@@@@@@                                  16250    
              32 |@@@@@@@@@@@@@                            32060    
              64 |@@@@@@@@@@@@@@                           35947    
             128 |                                         0        

  latency                                           
           value  ------------- Distribution ------------- count    
            2048 |                                         0        
            4096 |@@@@@@@@@@@@@@@@                         438      
            8192 |@@@@@@@@@@@@@@@@@@@@@@                   575      
           16384 |@                                        38       
           32768 |                                         4        
           65536 |                                         4        
          131072 |                                         0        
          262144 |                                         4        
          524288 |                                         1        
         1048576 |                                         2        
         2097152 |                                         0        

Surely adding a second action for the same probe shouldn''t change the
behaviour of the first action ... right?
 
 
This message posted from opensolaris.org

btw I''m on snv_44 if that makes any difference ...

Chip - your tick-n based script works fine on my machine too - but I
can''t see what is different about my script.
 
 
This message posted from opensolaris.org

Matt,

I''m confused.  Each run only matches 2 probe clauses.  If you had only 
un-commented the second clause, DTrace should say that it matched 3 
probes (even though there are only 2 actual probes).

Chip

Matt Stupple wrote:
> I''m *not* sure the enqueue probe is firing - but I don''t
understand why it wouldn''t be.
>
> To be specific here''s my real .d script:
>
> fwtools$target:::workpool-enqueue
> / rand() % 101 == 0 /
> {
> 	entrytimes[arg1] = timestamp;
> }
>
> /*
> fwtools$target:::workpool-enqueue
> {
> 	@["random"] = quantize(rand() % 101)
> }
> */
>
> fwtools$target:::workpool-dequeue
> / entrytimes[arg1] > 0 /
> {
> 	@["latency"] = quantize(timestamp - entrytimes[arg1]);
> 	entrytimes[arg1] = 0;
> }
>
> Which I run like this (the parameters to the testwpool_performance binary
aren''t relevant to this discussion):
>
> $ dtrace -s testpool.d -c ''testwpool_performance 10 2
100000''
>
> ... and get this output ...
>
> dtrace: script ''testpool.d'' matched 2 probes
> dtrace: pid 7681 has exited
>
> However, if I uncomment the second action block in my script then I get
this instead:
>
> dtrace: script ''testpool.d'' matched 2 probes
> dtrace: pid 7712 has exited
>
>   random                                            
>            value  ------------- Distribution ------------- count    
>               -1 |                                         0        
>                0 |                                         910      
>                1 |                                         975      
>                2 |@                                        1988     
>                4 |@@                                       3936     
>                8 |@@@                                      7934     
>               16 |@@@@@@@                                  16250    
>               32 |@@@@@@@@@@@@@                            32060    
>               64 |@@@@@@@@@@@@@@                           35947    
>              128 |                                         0        
>
>   latency                                           
>            value  ------------- Distribution ------------- count    
>             2048 |                                         0        
>             4096 |@@@@@@@@@@@@@@@@                         438      
>             8192 |@@@@@@@@@@@@@@@@@@@@@@                   575      
>            16384 |@                                        38       
>            32768 |                                         4        
>            65536 |                                         4        
>           131072 |                                         0        
>           262144 |                                         4        
>           524288 |                                         1        
>          1048576 |                                         2        
>          2097152 |                                         0        
>
> Surely adding a second action for the same probe shouldn''t change
the behaviour of the first action ... right?
>  
>  
> This message posted from opensolaris.org
> _______________________________________________
> dtrace-discuss mailing list
> dtrace-discuss at opensolaris.org
>

> Matt,
> 
> I''m confused.  Each run only matches 2 probe clauses.
>  If you had only 
> n-commented the second clause, DTrace should say that
> it matched 3 
> probes (even though there are only 2 actual probes).
Just a cut-n-paste error I''m afraid, with the second clause
un-commented I *do* get ''dtrace: script ''testpool.d''
matched 3 probes''
 
 
This message posted from opensolaris.org