where does initialization time go?
where does initialization time go?
- Subject: where does initialization time go?
- From: Joel Reymont <email@hidden>
- Date: Fri, 28 Aug 2009 08:50:00 +0100
On Aug 28, 2009, at 12:33 AM, Jonas Maebe wrote:
The statistics that you posted previously show that dyld is only
taking about 50ms during Firefox' startup. Even if you could reduce
that by 90%, it wouldn't really make a lot of difference given the
total startup time. So I'm not sure where the low-hanging fruit is
here...
By low-hanging fruit I meant a measurement approach, not being able to
improve results. I thought it would be rather quick to test the shared
cache theory and prove it right or wrong.
It appears, though, that 1) under no circumstances does
update_dyld_shared_cache wants to put XUL in the cache, even if I try
to force it, and 2) it doesn't matter. Proving this was quick, thus
low-hanging fruit.
There's a large difference between cold startup dyld statistics
(25-50ms) and warm startup ones (700ms+). There's also a baffling lack
of difference between Firefox and Safari cold stats, despite Safari
pulling everything from the cache and Firefox using a large number of
non-cached dylibs.
Do these results mean that I should be digging somewhere else?
If so then I cannot explain the difference between startup time as
reported by my DTrace script and the dyld statistics. Note that I'm
using the Apple 256Gb SSD in my 2.93Ghz unibody MacBook Pro.
I thought initially that startup time reported by DTrace should equal
the statistics reported by dyld but it's a difference of less than 1s
for dyld and almost 10s for dtrace.
Here are the gory details...
cold startup for Safari
---
sync && purge && DYLD_PRINT_STATISTICS=1 /Applications/Safari.app/
Contents/MacOS/Safari
total time: 696.9 milliseconds (100.0%)
total images loaded: 116 (114 from dyld shared cache, 114 needed no
fixups)
total segments mapped: 5, into 30 pages with 10 pages pre-fetched
total images loading time: 204.9 milliseconds (29.4%)
total rebase fixups: 1,298
total rebase fixups time: 0.1 milliseconds (0.0%)
total binding fixups: 2,476
total binding symbol lookups: 234, average images searched per symbol:
1.6
total binding fixups time: 80.5 milliseconds (11.5%)
total bindings lazily fixed up: 3 of 901
total init time time: 411.3 milliseconds (59.0%)
total images with weak exports: 1
---
cold startup for Firefox
---
total time: 731.2 milliseconds (100.0%)
total images loaded: 106 (93 from dyld shared cache, 56 needed no
fixups)
total segments mapped: 49, into 5903 pages with 684 pages pre-fetched
total images loading time: 235.3 milliseconds (32.1%)
total rebase fixups: 149,011
total rebase fixups time: 3.7 milliseconds (0.5%)
total binding fixups: 24,932
total binding symbol lookups: 797, average images searched per symbol:
2.3
total binding fixups time: 149.9 milliseconds (20.5%)
total bindings lazily fixed up: 45 of 19,109
total init time time: 342.2 milliseconds (46.8%)
total images with weak exports: 3
---
Startup as measured by DTrace
---
./cold.sh startup.d
Total: 10001.723521ms
---
My DTrace script measures time to reach a static probe that fires as
soon as main is entered. I thought that the only thing that happens
before main is the fixup of shared libraries and the running of static
initializers.
It only takes 0.3s to run the initializers according to dyld above.
Where did the other 9.7s go?
cold.sh is rather simple
---
#!/bin/bash
cmd="./Minefield.app/Contents/MacOS/firefox-bin -no-remote -foreground
-P 2"
sync && purge && dtrace -x dynvarsize=64m -x evaltime=exec -c "$cmd" -
wZs $1
---
and the startup.d script doesn't do much either
---
#pragma D option quiet
BEGIN
{
start = timestamp;
}
/* stop tracing here */
mozilla$target:::main-entry
{
exit(0);
}
END
{
this->total = timestamp - start;
printf("Total: %u.ums\n", this->total / 1000000, this->total %
1000000);
}
---
Just in case, here are the warm startup stats for Firefox
total time: 25.9 milliseconds (100.0%)
total images loaded: 106 (93 from dyld shared cache, 56 needed no
fixups)
total segments mapped: 49, into 5903 pages with 684 pages pre-fetched
total images loading time: 5.6 milliseconds (21.7%)
total rebase fixups: 149,011
total rebase fixups time: 3.0 milliseconds (11.6%)
total binding fixups: 24,932
total binding symbol lookups: 797, average images searched per symbol:
2.3
total binding fixups time: 3.0 milliseconds (11.6%)
total bindings lazily fixed up: 45 of 19,109
total init time time: 14.3 milliseconds (55.0%)
total images with weak exports: 3
---
fastest mac firefox!
http://wagerlabs.com
_______________________________________________
Do not post admin requests to the list. They will be ignored.
Darwin-dev mailing list (email@hidden)
Help/Unsubscribe/Update your Subscription:
This email sent to email@hidden