Re: where does initialization time go?
site_archiver@lists.apple.com Delivered-To: darwin-dev@lists.apple.com Startup as measured by DTrace --- ./cold.sh startup.d Total: 10001.723521ms --- 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 Eric 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); } Just in case, here are the warm startup stats for Firefox --- fastest mac firefox! http://wagerlabs.com _______________________________________________ Do not post admin requests to the list. They will be ignored. Darwin-dev mailing list (Darwin-dev@lists.apple.com) Help/Unsubscribe/Update your Subscription: http://lists.apple.com/mailman/options/darwin-dev/site_archiver%40lists.appl... On Aug 28, 2009, at 12:50 AM, Joel Reymont wrote: 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. 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 --- I am afraid that the data collected using this methodology is highly suspect. - firefox-bin gets run as root This is not a normal environment for an application. There are plenty of high-level frameworks which are not quite happy running in that environment, in good part because the root user will not have a typical home directory setup and due to differences in environment variables. This is a known limitation of dtrace -c . Feel free to add your voice via bugreporter.apple.com - A typical launch is not just fork/exec or posix_spawn Even if dtrace -c could magically launch using a regular user, it still isn't a typical launch. dtrace uses fork/exec or posix_spawn (I didn't check which one), while a typical launch (Dock, Finder, open) uses LaunchServices. It isn't all that different but you might as well address both issues together. I'd recommend reworking your script to watch the exec-success of firefox-bin and use a static probe (no need for $target then) to mark the end time. Then you can use a more normal launch method, for example open .../Minefiled.app . - purge(8) is not the way to get a cold launch purge leaves the system in a state that is highly unrealistic. A recently booted system will have a great deal of useful content in the buffer cache that purge throws away. You'll be measuring a launch which involves a lot of page-ins which will not occur on a typical user configuration. In some cases this can point to issues which also occur in a real cold launch, but it is very likely to waste your time. To get a real cold launch, there is no workaround, you have to reboot. It gets worse due to the BootCache capturing IOs during a boot and replaying those IOs (optimized) during the next boot. This recording will last about 60s from the time launchd starts executing, although this detail is subject to change without notice. So you really have to: - boot your system, wait >60s, launch - repeat Discard the first measurement unless you are certain that the initial boot cache playlist did not contain your launch IOs. And yes, it is a pain :-( - Using a SSD to measure cold launch is not representative of a typical user. A cold launch using a SSD is much closer to a warm launch using a good old mechanical hard drive. Optimizing this scenario will not necessarily improve the experience of your users. END { this->total = timestamp - start; printf("Total: %u.%06ums\n", this->total / 1000000, this->total % 1000000); } --- 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 This email sent to site_archiver@lists.apple.com
participants (1)
-
Eric Gouriou