dtrace discuss - Aug 2009 - sum on an aggregation / summing values from different threads

I''m trying to calculate the run time of all the initializers in  
Firefox [1]. I''m placing the initialization time by library into an  
aggregation but I also need the sum of all the values in the  
aggregation. Is there an easy way to achieve this with D?

I tried using a static variable (see startup.d) but initializers are  
being run in different threads and they overwrite my global counter.

	Thanks, Joel

[1]
http://github.com/wagerlabs/firefox-startup/blob/bd2047f763511b7a016ddf4c66fad0611ae722c9/startup.d

---
fastest mac firefox!
http://wagerlabs.com

On Mon, Aug 24, 2009 at 1:50 PM, Joel Reymont<joelr1 at gmail.com>
wrote:
> I''m trying to calculate the run time of all the initializers in
Firefox [1].
> I''m placing the initialization time by library into an aggregation
but I
> also need the sum of all the values in the aggregation. Is there an easy
way
> to achieve this with D?
>
> I tried using a static variable (see startup.d) but initializers are being
> run in different threads and they overwrite my global counter.
>
Why not just use a separate aggregation for this?  For example, in
this one clause, you could do this:

pid$target::ImageLoader??runInitializers*:return
/self->ts && self->lib != 0/
{
  this->delta = timestamp - self->ts;
  @initint = sum(this->delta / 1000000000);
  @initfrac = sum(this->delta % 1000000000);
  @int[self->lib] = sum(this->delta / 1000000000);
  @frac[self->lib] = sum(this->delta % 1000000000);
  self->lib = 0;
  self->ts = 0;
}

And then print the value with a printa() statement:

  printa("Static init: %@u.%@03us for %s\n", @int, @frac);
  printa("Static initialization: %@u.%@03us\n", @initint, @initfrac);

Chad

On Aug 24, 2009, at 7:02 PM, Chad Mynhier wrote:
> Why not just use a separate aggregation for this?  For example, in
> this one clause, you could do this:
That''s what I tried but the result wasn''t any different.

I think what''s happening is that multiple threads try to write back to
the global/aggregation at the same time and values get written over.

Here''s an example...

pid$target::ImageLoader??runInitializers*:return
/self->ts && self->lib != 0/
{
   ...
   @initint = sum(this->delta / 1000000000);
   @initfrac = sum(this->delta % 1000000000);
   printa("---> %@u.%@03us\n", @initint, @initfrac);
   ...
}

This produces the following timings:

---> 0.199488s
---> 0.199488s
---> 0.249219s
---> 0.341708s
---> 0.341708s
---> 0.425014s
---> 0.425014s
---> 0.473674s
---> 0.592053s
---> 0.592053s
---> 0.736120s
---> 0.736120s
---> 0.736120s
---> 0.830530s
---> 0.881503s

The final 0.88 above is not right, though, as seen in the per-library  
timings:

Static init: 0.29539s for /System/Library/Frameworks/ 
CoreServices.framework/Versions/A/Frameworks/CarbonCore.framework/ 
Versions/A/CarbonCore
Static init: 0.36176s for /Users/joelr/Work/mozilla/startup/./ 
Minefield.app/Contents/MacOS/libsoftokn3.dylib
Static init: 0.40539s for /System/Library/Frameworks/Carbon.framework/ 
Frameworks/HIToolbox.framework/Versions/A/HIToolbox
Static init: 0.48660s for /System/Library/Frameworks/ 
ApplicationServices.framework/Versions/A/Frameworks/ 
CoreGraphics.framework/Versions/A/Resources/libCGATS.A.dylib
...

Just these few are > 0.88s.

	Thanks, Joel

[1]
http://github.com/wagerlabs/firefox-startup/commit/baeed3b4ac9eef7ebba13ff5bdc6928bfb2ca83f

---
fastest mac firefox!
http://wagerlabs.com

Here''s the full output:

http://pastie.org/593398

You can see that the total should be way higher than 0.81s by  
eyeballing the output.

The total should be between 3 and 4 seconds.

	Thanks, Joel

---
fastest mac firefox!
http://wagerlabs.com

On Mon, Aug 24, 2009 at 2:31 PM, Joel Reymont<joelr1 at gmail.com>
wrote:
> Here''s the full output:
>
> http://pastie.org/593398
>
> You can see that the total should be way higher than 0.81s by eyeballing
the
> output.
>
> The total should be between 3 and 4 seconds.
>
You''re printing the values incorrectly.  Here''s the hint:

---> 0.28538s
---> 0.190297s
---> 0.289448s
---> 0.289448s
---> 0.405153s

If these were ascending, you wouldn''t see the .28538 first. 
You''re
missing leading zeros on the fractional part of the number.

I summed the per-library values using this assumption, and they add up
correctly to 818968, which matches the final value for
@initint/@initfrac:

---> 0.818968s

Chad

Any suggestions on how I can figure out the right # of leading 0s?

I really wish dtrace had floating-point printing.

	Thanks, Joel

On Aug 24, 2009, at 7:40 PM, Chad Mynhier wrote:
> You''re printing the values incorrectly.  Here''s the hint:
>
> ---> 0.28538s
> ---> 0.190297s
> ---> 0.289448s
> ---> 0.289448s
> ---> 0.405153s
>
> If these were ascending, you wouldn''t see the .28538 first. 
You''re
> missing leading zeros on the fractional part of the number.
---
fastest mac firefox!
http://wagerlabs.com

On Mon, Aug 24, 2009 at 3:07 PM, Joel Reymont<joelr1 at gmail.com>
wrote:
> Any suggestions on how I can figure out the right # of leading 0s?
>
> I really wish dtrace had floating-point printing.
>
This should do what you want:

printa("%@09d\n", @int);

i.e., print it in a field 9 characters wide with leading 0''s.  For
example:

x2200# dtrace -qn ''BEGIN{@int =
sum(28538);printa("0.%@09d\n", @int);exit(0)}''
0.000028538

x2200#