DTrace Mozilla - some trunc weirdness with image timings
By jmr on Sep 18, 2007
Well I had blogged about image timings for Mozilla using our custom load probes a few days ago, but when I looked at the output I noticed a little weirdness. The final top 10 site listing with Count, Avg and Sum had some Count entries of 0.
PID UID COUNT AVG(msec) SUM(msec) SITE
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/133-1321718550
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/178-1321865092
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/76-1321412015
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/83-1321462309
10955 65535 1 0 0 moz-anno:favicon:http://www.mozilla.org/2005/made-up-favicon/84-1321463278
10955 65535 0 4 4 file:///usr/share/doc/soldevex/html/images/Solaris.gif
10955 65535 0 7 7 http://www.makepovertyhistory.org/whiteband_small_right.gif
10955 65535 0 7 7 file:///usr/share/doc/soldevex/html/images/New_Prod_Banner.jpg
10955 65535 0 12 12 http://www.mozilla.org/images/header_tab.gif
10955 65535 0 26 26 http://docs.sun.com/app/images/shadow_box.png
10955 65535 0 62 62 http://www.abercornbasin.com/items/ar02_eflyer.jpg
Now this seemed a little weird, I wondered if having the count aggregation in the start probe and the avg/ sum aggregates in the done probes was causing problems and getting things out of sync. So I changed that but no joy, still got some zero counts. I tested just listing the site aggregate and all the Counts in that looked fine, no 0's. So it was something to do with combining the aggregates that was causing the problem.
Chewing this over on irc.mozilla.org #developers with Brendan Gregg turns out that the problem is in the trunc calls, thanks for the prompting Brendan, think I'd still be looking at it When we trunc the count, avg and sum aggregates they have all been sorted off different things, namely count, avg or sum So the list of truncated sites you get for each of the aggregates will probably not be the same. When you then combine them in one aggregate printout, dtrace will just insert 0 for the Count if that particular URI is not present in the count aggregate but is in the other two aggregates. It is the aggregate you are sorting on that takes precedence.
If you have aggregates sorted on different values and want to combine them into one aggregate printa do not truncate them first. Or if you really need to truncate them just truncate them, but list them separately, which is what I've done. The new improved output listing is here, along with the modified script.