Firefox/Projects/Startup Time Improvements/joelr notes

From MozillaWiki
Jump to: navigation, search

Intro

I'm trying to figure out where Firefox startup time goes, up to the return from BrowserStartup (Javascript function). I'm also manipulating DTrace into telling me where time is going, without making any assumptions.

Current status

September 23, 2009

x86-64

I now have x86-64 Firefox up and running on Snow Leopard. Josh Aas did all the work, I just put on the final touches.

A shiny new world

Damon thinks I should help Josh with the 64-bit port. 64-bit Trace Monkey gives us a 20% improvement in speed which beats the 5% DWARF improvement from -fomit-frame-pointer.

I didn't know it was my birthday. I'm leaving the 32-bit world behind. 64 bits here I come!

Previous statuses

September 22, 2009

I have two bottlenecks on my plate, Bug 517045 and Bug 517576. Both of them may not be possible to speed up significantly, not without a large research effort. The former requires consultation with the owners and the later requires me to become a layout expert.

Benjamin Smedberg suggested taking care of DWARF symbols in breakpad as that will let us use the -fomit-frame-pointer gcc option. Omitting the frame pointer would result in at least a 5% overall speed up because a register will be freed on x86-32.

DWARF is a tree of dependent bugs, though, and Jim Blandy is working on them. Jim is a Linux guy, though, and also has ECMAScript 5 strict mode to take care of whereas I'm strictly focused on performance optimization.

I'll ask management to see if I can work on DWARF with Jim.

September 21, 2009

Wins

Kudos to Masayuki for fixing Bug 517549. It's hard to believe but it looks like our Mac Ts [{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22169%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22173%22},{%22test%22:%2216%22,%22branch%22:%221%22,%22machine%22:%22178%22}&sel=1252833380,1253542320 went down 30%] and it was only 12.3% of my startup. I wonder what happens when Bug 517576 gets fixed, that's 21% of my startup!

One other thing I'm wondering about... What if all the bottlenecks I find will get fixed by someone else? Damon wants me to write code!!!

September 16, 2009

That mysterious forking

Apparently, Firefox forks the first time after a build to rebuild caches, etc. Need to make sure to profile from the 2nd run on. This forking behavior baffled me when I started with DTrace.

I'm an idiot

I spent a month becoming an expert on DTrace, only to realize that it's not very useful to get a global picture of the bottlenecks because the overhead of tracing everything is so high!

Shark is a much better tool to get a global picture, specially using "Time profile all states" which allocates time spent blocking to the calling function. I overlooked this initially since I did not zero in on the right thread, the one that has start and XRE_main or exit. Without this it looks like Firefox is spending most of its time waiting on threads and Mach messages.

Timing startup

A clear picture courtesy of Shark

	0.0%	92.8%	firefox-bin	start
	0.0%	92.8%	firefox-bin	 main
	0.0%	91.6%	XUL	  XRE_main
	0.0%	40.8%	XUL	   nsAppStartup::CreateHiddenWindow()
	0.0%	34.7%	XUL	   ScopedXPCOMStartup::Initialize()
	0.0%	6.4%	XUL	   ScopedXPCOMStartup::~ScopedXPCOMStartup()
	0.0%	3.4%	XUL	   ScopedXPCOMStartup::SetWindowCreator(nsINativeAppSupport*)
	0.0%	2.4%	XUL	   nsXPTCStubBase::Stub3()
	0.0%	0.8%	XUL	   nsAppStartupNotifier::Observe(nsISupports*, char const*, unsigned short const*)
	0.0%	0.8%	HIToolbox	   GetCurrentEventKeyModifiers
	0.0%	0.6%	XUL	   nsXREDirProvider::DoStartup()
	0.0%	0.5%	XUL	   RemoveComponentRegistries(nsIFile*, nsIFile*, int)
	0.0%	0.4%	XUL	   NS_NewToolkitProfileService(nsIToolkitProfileService**)
	0.0%	0.3%	XUL	   nsToolkitProfile::Lock(nsIProfileUnlocker**, nsIProfileLock**)
	0.0%	0.1%	XUL	   WriteVersion(nsIFile*, nsCString const&, nsCString const&, nsIFile*, nsIFile*)
	0.0%	0.1%	XUL	   nsINIParser_internal::Init(nsILocalFile*)
	0.0%	0.1%	XUL	   LaunchChildMac
	0.0%	0.4%	XUL	  XRE_GetBinaryPath
	0.3%	0.4%	XUL	  XRE_CreateAppData
	0.4%	0.4%	XUL	  NS_LogInit_P
	0.0%	6.2%	dyld	_dyld_start
	1.0%	1.0%	libSystem.B.dylib	_exit

September 14, 2009

Breaking startup into smaller chunks

bsmedberg:joelr: I really think that "Ts" is still much too large of a chunk to make meaningful improvements on
bsmedberg:joelr: in order to make meaninful discoveries, I think you have to break startup down into pieces and then maybe improve each piece
joelr:bsmedberg: i'm listening
bsmedberg:well, you've got various stuff that happens up until you start the event loop
bsmedberg:breaking XRE_main into phases up until nsAppStartup::Run would be interesting
bsmedberg:I still haven't seen a graph or anything of how we break down
bsmedberg:joelr: I think stepping through in a debugger might give you a better sense of what's going on (up until Run()) than profiles would
bsmedberg:even if you broke things up into "from main() to the beginning of event loop" and "after the event loop starts" that would be more interesting
bsmedberg:joelr: and then within the first chunk, timing NS_InitXPCOM, the extension manager bits, chromereg startup
bsmedberg:joelr: I think this intersects with some of the startup-timeline stuff taras was doing
joelr:bsmedberg: what are the functions for "extension manager bits" and "chromereg startup"?
bsmedberg:joelr: basically from http://mxr.mozilla.org/mozilla-central/source/toolkit/xre/nsAppRunner.cpp#2607 to #3453
joelr:bsmedberg: thanks for the suggestion, i'll do that
bsmedberg:joelr: #3382 to #3408 or so

XUL reflow

bz:joelr: so I'm still wondering about some of the reflow stuff
bz:joelr: I know it's hard, but that's why no one's really dived into it yet
bz:joelr: and I'd love to know whether we do in fact end up looping significantly in sprocket layout during startup, for example
joelr:bz: i'm still wondering about reflow myself but i'm not quite ready to tackle it yet
joelr:bz: don't know enough

XPT_ArenaMalloc and zero-filling memory

Closed Bug 516241. There's no evidence that zero-filling memset is a bottleneck. DTrace cannot latch onto the return from memset on Snow Leopard, so I can't time it. All I know is that it's called 133,245 times during startup and zero-fills 14,851,995 bytes of memory.

bsmedberg:joelr: do you have evidence that the calloc is hurting? It really
doesn't sound like something that would take a lot of time
bsmedberg:there's no IO, and arena pages are roughly page-sized, right?
joelr:bsmedberg: i don't have evidence that it's hurting, not at all. i just
see it in the startup path a lot.
bsmedberg:"see it" in what way?
joelr:bsmedberg: there's no IO but arena pages are not page-sized. they are 1k
blocks whereas pages are 4k
joelr:bsmedberg: i'm dtracing startup, all functions, that's how i see it
bsmedberg:it's less than a page, then... you really shouldn't be having
memory-thrashing issues with the calloc
bsmedberg:joelr: you mean it takes time, or its just a callcount?
bsmedberg:I'm a little skeptical that the arena actually helps at all, but
that's a different matter.
joelr:bsmedberg: call count, i suppose. i'm also skeptical that arena helps at
all since mac osx has it's own memory allocation optimizations
bsmedberg:And the xpt code has no tests, so unles you have a measured
performance problem I suggest not touching it.
joelr:bsmedberg: i see (tests)... well, i'll look into it a little bit more
since i want to measure a difference vs malloc (no zero-fill). it does crash
with malloc at the moment so i won't be looking into it too much.
bsmedberg:you'd have to basically zero-fill when you allocate items from the
arena
joelr:bsmedberg: because those items expect to be zero-filled?
bsmedberg:seems so, if you're crashing with malloc...
bsmedberg:joelr: ok, well, I'm saying "you have no evidence this bug is worth
fixing, please move on"

September 11, 2009

Reflows

taras: joelr: btw, you gave up on reflows?
taras: that makes me sad
taras: i was hoping we'd end up with some sort of tool to measure cost of laying out various xul components
joelr: taras: i did not give up, i just don't know how to go about it yet
taras: so people could profile their guis
taras: instead of going at it blindly
joelr: taras: i didn't hear your prayers, my apologies
joelr: i'll make a note on the idea of a tool that measures guis, though
joelr: taras: how do i measure? from where to where?
joelr: layout? reflow? something else?
taras: joelr: it's simple, time how long they take
taras: just see long functions take to run, ones that trigger all those fun reflow stacks

Restarting from the ground up

I'm very comfortable with DTrace but still not comfortable with the Firefox code base. It will take me a while to grok reflow, for example, much less optimize it. I feel that there are startup speedups that can be achieved quicker, with a better return on investment (aka low-hanging fruit).

Yes, reflow is in the hot path during startup but it's not clear if it's a major source of slowness. I would like to know what happens during Firefox startup, in as much detail as possible and DTrace has granted me my wish in the form of a 400Mb+ log file. The file lists all the function calls up to the return from the JS function BrowserStartup, e.g.

...
    6200       .      .           -> ImageLoaderMachO::segIsReadOnlyImport(unsigned int) const(0x8FE46820, 0x1, 0xBFFFC1C8)             
    6202       .      .             -> ImageLoaderMachOCompressed::segmentCommandOffsets() const(0x8FE46820, 0x0, 0x0)          
    6203      81      1             <- ImageLoaderMachOCompressed::segmentCommandOffsets() const = 10
    6205     270      4           <- ImageLoaderMachO::segIsReadOnlyImport(unsigned int) const = 116
    6206       .      .           -> ImageLoaderMachO::segFileOffset(unsigned int) const(0x8FE46820, 0x1, 0xBFFFC1C8)           
    6208       .      .             -> ImageLoaderMachOCompressed::segmentCommandOffsets() const(0x8FE46820, 0x0, 0x0)          
...

There are obviously interesting bits here. How can we piggyback on the ImageLoaderMachOCompressed for example?

Minimizing file system access provides a good return on investment since it apparently takes a few milliseconds on mobile devices. I'm focusing on this first and foremost since we do have file system access in the midst of dynamic linker static initialization, e.g.

20974362 861470 708476        <- xptiSortFileList(void const*, void const*, void*) = 622
20974385 . .        -> xptiSortFileList(void const*, void const*, void*)(0x3050F9C, 0x3050F7C, 0xBFFFEBC0)		
20974394 . .        -> nsACString_internal::nsACString_internal(char*, unsigned int, unsigned int)(0xBFFFE978, 0xBFFFE98C, 0x0)		
20974397 113 2        <- nsACString_internal::nsACString_internal(char*, unsigned int, unsigned int) = 24
20974400 . .        -> nsACString_internal::nsACString_internal(char*, unsigned int, unsigned int)(0xBFFFE924, 0xBFFFE938, 0x0)		
20974402 112 2        <- nsACString_internal::nsACString_internal(char*, unsigned int, unsigned int) = 24
20974424 . .        -> nsLocalFile::GetNativeLeafName(nsACString_internal&)(0x3083600, 0xBFFFE978, 0x40)		
20974427 . .        -> objc_exception_try_enter(0xBFFFE868, 0xE000002, 0x181A4)		

It may be interesting to study the startup path of Chromium and Safari.

September 9, 2009

Reflow optimization

I've been thinking about speeding up reflows (Bug 514275) but did not make progress until I got Boris Zbarsky involved. There are tons and tons of classes that reflow and I'm completely unfamiliar with that code.

Boris suggested restricting invocations of PresShell::ProcessReflowCommands to those that actually do work

0 != mDirtyRoots.Length()

on XUL documents

FrameManager()->GetRootFrame()->GetFirstChild(nsnull) &&
FrameManager()->GetRootFrame()->GetFirstChild(nsnull)->GetType() == nsGkAtoms::rootFrame

Looking at the 25 reflows and timings for the "Getting involved with Mozilla..." page, it's clear that some reflows are more expensive than others. It's also interesting that there are just 11 reflows for a blank page.

bz: 1) try to reduce number of reflows
bz: (e.g. make text controls not reflow sync in this setup if we can; reduce the number of text value sets if we can't)
bz: Or see whether the reflow events we get are really needed (e.g. if the load is not done yet, why are they happening?)
bz: But separately, it looks like reflows seem to be generally expensive

Performance measurement

Using Vlad's benchmark, I have 5.3s cold start and 0.9s warm start. Timing using the return from BrowserStartup (JS) gives me almost exactly the same results as Vlad's.

javascript*:::function-return
/copyinstr(arg2) == "BrowserStartup"/
{
  exit(1);
}

The difference is about 50ms which copyinstr probably accounts for.

September 3, 2009

On reflow...

bz:so there are a few things we could talk about:
bz:1) make any given reflow pass faster (this is hard)
bz:2) reduce number of reflow passes
bz:s/this is hard/this may be hard/
bz:So one place to start would be seeing why we're doing reflow at all
bz:that is, what things cause posting of reflow events and what things trigger reflow in their post-reflow callbacks
bz:and seeing whether we can reduce or eliminate them.
joelr:post-reflow callbacks?
bz:see comment 1 in the bug
bz:firefox has about 4000 elements in its ui
bz:which means about 4000 boxes to reflow
bz:modulo optimizations, etc
bz:BoxReflow is the reflow of a single box
bz:those are the two things to look into
bz:reducing number of reflow passes
bz:and speeding up individual passes
bz:if you have info on what parts actually take up time during reflow, we should look into that
bz:I would also be interested in the number of nsIFrame::Layout calls you see during startup
bz:that's a more interesting metric to me
bz:esp. if we can chunk it up per reflow pass

A reflow pass is PresShell::ProcessReflowCommands which can re-enter itself via post-reflow callbacks.

Bug 514275

September 2, 2009

My previous stack traces were all bogus since symbols are stripped during packaging. This is all sorted out now using this config (for Snow Leopard):

export CC="gcc-4.2 -arch i386"
export CXX="g++-4.2 -arch i386"
ac_add_options --target=i386-apple-darwin8.0.0
ac_add_options --with-macos-sdk=/Developer/SDKs/MacOSX10.5.sdk
ac_add_options --enable-macos-target=10.5

export HOST_CC="gcc-4.2"
export HOST_CXX="g++-4.2"
export RANLIB=ranlib
export AR=ar
export AS=$CC
export LD=ld
export STRIP="strip -x -S"
export CROSS_COMPILE=1
export MOZ_DEBUG_SYMBOLS=1

. $topsrcdir/browser/config/mozconfig
mk_add_options MOZ_OBJDIR=@TOPSRCDIR@/objdir-release-profiling
mk_add_options MOZ_MAKE_FLAGS=-j2
ac_add_options --disable-tests
ac_add_options --disable-crashreporter
ac_add_options --enable-dtrace
ac_add_options --enable-libxul
ac_add_options --enable-optimize
ac_add_options --enable-debugger-info-modules
ac_add_options --disable-strip
ac_add_options --disable-install-strip

I'm getting 3-5s from cold start to return from BrowserStartup (JavaScript), e.g.

./d firefox-bin startup.d stop-js.d 
dtrace -Zqw -x dynvarsize=64m -x evaltime=preinit -p 55752  -s startup.d -s stop-js.d -s sigcont.d

Total: 5000.294085ms

./d firefox-bin startup.d stop-js.d 
dtrace -Zqw -x dynvarsize=64m -x evaltime=exec -p 55855  -s startup.d -s stop-js.d -s sigcont.d

Total: 3387.623720ms

The hot path for those 5s looks like this:

./d firefox-bin hotpath.d stop-js.d 
dtrace -Zqw -x dynvarsize=64m -x evaltime=preinit -p 55765  -s hotpath.d -s stop-js.d -s sigcont.d
kill -CONT 55765

  XUL`nsFrame::BoxReflow(nsBoxLayoutState&, nsPresContext*, nsHTMLReflowMetrics&, nsIRenderingContext*, int, int, int, int, int)             1382
  firefox-bin`0x0                                                 623
  XUL`nsHTMLInputElement::GetReadOnly(int*)                        53
  XUL`nsOverflowContinuationTracker::Insert(nsIFrame*, unsigned int&)               48
  XUL`MapAttributesIntoRule(nsMappedAttributes const*, nsRuleData*)               24
  XUL`nsBlockFrame::Reflow(nsPresContext*, nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&)               20
  XUL`nsColumnSetFrame::ReflowChildren(nsHTMLReflowMetrics&, nsHTMLReflowState const&, unsigned int&, nsColumnSetFrame::ReflowConfig const&, int, nsCollapsingMargin*, nsColumnSetFrame::ColumnBalanceData&)               18
  XUL`DocumentViewerImpl::PageHide(int)                            18
  XUL`nsBlockFrame::DoReflowInlineFrames(nsBlockReflowState&, nsLineLayout&, nsLineList_iterator, nsFlowAreaRect&, int&, nsFloatManager::SavedState*, int*, LineReflowStatus*, int)               14
  XUL`non-virtual thunk to nsHTMLInputElement::Release()               11
...

August 30, 2009

Using my "Lego blocks" DTrace toolchain I thought I would check the "hot paths" through Firefox code during the first 20 seconds of startup.

./d firefox-bin hotpath.d stop-20s.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=preinit -p 1478  -s hotpath.d -s stop-20s.d -s sigcont.d
kill -CONT 1478

  XUL`gfxContextAutoSaveRestore::Reset(gfxContext*)              2766
  firefox-bin`0x0                                                2234
  XUL`operator new(unsigned long, void*)                          348
  XUL`gfxImageSurface::Height() const                             335
  XUL`gfxPattern::Release()                                        60
  XUL`DumpJSValue                                                  44
  XUL`gfxContextAutoSaveRestore::gfxContextAutoSaveRestore(gfxContext*)               29
  XUL`gfxUserFontSet::Release()                                    17
  XUL`gfxImageSurface::Data() const                                16
  XUL`gfxContextPathAutoSaveRestore::~gfxContextPathAutoSaveRestore()                8

I'm sampling at 997Hz so that's roughly 2.7s for the top result. A small script is all it took to see where gfxContextAutoSaveRestore::Reset is being called from.

BEGIN
{
  i = 0;
}

pid$target::gfxContextAutoSaveRestore??Reset(gfxContext*):return
/ i < 10 /
{
  printf("arg0: 0x%x, arg1: 0x%x\n", arg0, arg1);
  ustack();
  i++;
}

pid$target::gfxContextAutoSaveRestore??Reset(gfxContext*):return
/ i >= 10 / 
{
  exit(0);
}

The stack traces (first one of ten below) include gfxImageSurface::Height and DumpJSValue.

./d firefox-bin autosave.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=preinit -p 1527  -s autosave.d -s sigcont.d
kill -CONT 1527
arg0: 0x90, arg1: 0x1a71da8

              XUL`gfxContextAutoSaveRestore::Reset(gfxContext*)+0x90
              XUL`gfxImageSurface::Height() const+0x2d976
              XUL`gfxImageSurface::Height() const+0x135b6
              XUL`gfxImageSurface::Height() const+0x107b7
              XUL`non-virtual thunk to nsPrintSession::QueryInterface(nsID const&, void**)+0x53d16
              XUL`non-virtual thunk to nsPrintSession::QueryInterface(nsID const&, void**)+0x53f1b
              XUL`NS_GetComponentRegistrar_P+0x21cd
              XUL`NS_GetComponentRegistrar_P+0x2324
              XUL`NS_GetComponentRegistrar_P+0x4964
              XUL`non-virtual thunk to nsPrintSession::QueryInterface(nsID const&, void**)+0x4b3fd
              XUL`non-virtual thunk to nsPrintSession::QueryInterface(nsID const&, void**)+0x4b850
              XUL`non-virtual thunk to nsPrintSession::QueryInterface(nsID const&, void**)+0x4a9e1
              XUL`DumpJSValue+0x1dfbab
              XUL`DumpJSValue+0x1e0103
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0xc9e8e
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0xb64b4
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0xbb918
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0x151bdf
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0x14e234
              XUL`gfxCornerSizes::gfxCornerSizes(gfxSize const&, gfxSize const&, gfxSize const&, gfxSize const&)+0x14ed99

gfxImageSurface::Height is low-hanging fruit, defined as

PRInt32 Height() const { return mSize.height; }

I would suggest making it inline and checking startup time again.

DumpJSValue is trickier because it appears to be a JavaScript API function. Still, it's called during the static initialization portion of dynamic linking and all that printing is not helping in a release version of Firefox.

./d firefox-bin dump-js-value.d
dtrace -Zqw -x dynvarsize=64m -x evaltime=preinit -p 1579  -s dump-js-value.d -s sigcont.d
kill -CONT 1579

              XUL`DumpJSValue+0x3917
              XUL`DumpJSValue+0x3b92
              XUL`0x111c146
              XUL`0x111c161
              dyld`ImageLoaderMachO::doModInitFunctions(ImageLoader::LinkContext const&)+0xeb
              dyld`ImageLoader::recursiveInitialization(ImageLoader::LinkContext const&, unsigned int)+0xf6
              dyld`ImageLoader::recursiveInitialization(ImageLoader::LinkContext const&, unsigned int)+0x9a
              dyld`ImageLoader::runInitializers(ImageLoader::LinkContext const&)+0x3d
              dyld`dyld::initializeMainExecutable()+0x86
              dyld`dyld::_main(macho_header const*, unsigned long, int, char const**, char const**, char const**)+0x105d
              dyld`dyldbootstrap::start(macho_header const*, int, char const**, long)+0x30b
              dyld`_dyld_start+0x27
              firefox-bin`0x1000

I suppose the invocation should only be compiled in in a debug version of Firefox but I'm still searching for that invocation!

August 28, 2009

Eric Gouriou on my prior use of dtrace -c...:

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 .

I did rework my cold start script which can be used like this now:

./d firefox-bin startup.d stop-main.d 
dtrace -Zqw -x dynvarsize=64m -x evaltime=exec -p 35331 -s sigcont.d -s startup.d -s stop-main.d
kill -CONT 35331
Total: 2000.275985ms

The above assumes that I launch Minefield.app after d, from the dock, Finder, command line, etc.

August 27, 2009

The dyld shared cache lives in /var/db/dyld/. The two files of interest are dyld_shared_cache_i386.map (for x86-32) and shared_region_roots/Applications.paths. Both are regular text files. The former shows the contents of the shared cache for the i386 architecture and the latter is what update_dyld_shared_cache inspects.

There's no prebinding on newer versions of Mac OSX and the dyld shared cache is automatically updated as needed. Tracing Safari disk activity during startup reveals that basically all its dynamic libraries are pulled from the dyld shared cache.

It's possible to add Firefox (.../Firefox.app/Contents/MacOS/firefox-bin) to Applications.paths and the change will persist across reboots. Unfortunately, only a handful of libraries that Firefox uses are pulled into the cache by update_dyld_shared_cache. I'm speculating that this may have something to do with @executable_path/XUL and friends (otool -L .../firefox-bin).

Safari uses absolute paths to frameworks in /System/Library/Frameworks so I speculate that relative paths are what is preventing XUL and others from going into the cache. We may want to investigate /System/Library/Frameworks/Firefox.framework or similar.

Bug 513076.

It's possible to fix relative library paths in a given library, e.g. fix.sh XUL where fix.sh looks like this

#!/bin/bash 

function dylibs () {
  otool -L $1 |grep executable_path|awk '{print $1}'|cut -d"/" -f2
}

for i in `dylibs $1`
do
        install_name_tool -change @executable_path/$i `pwd`/$i $1
done

install_name_tool -id `pwd`/$1 $1

Firefox has to be recompiled with LDFLAGS=-header-pad_max_install_names in MOZCONFIG to make this happen since new library paths are greater than the space allocated in the Mach-O binary. See the man page for install_name_tool for details.

It's possible to force dynamic libraries into the cache by putting dynamic library paths into shared_region_roots/Applications.paths instead of executables. I wasn't successful in caching XUL, though, regardless of what I did.

In the end it doesn't seem to matter since there's 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.

Here's the cold startup stats 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

and 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

Notice a large and significant difference? Me neither.

The other thing that I cannot explain at the moment is where the rest of the startup time goes, e.g.

./cold.sh startup.d
Total: 10001.723521ms

So it took less than 1 second to dynamically link Firefox but where did the other 9 seconds of startup 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.%06ums\n", this->total / 1000000, this->total % 1000000);
}

I don't have an explanation yet but 9 seconds is a very large difference.

August 26, 2009

Suppose we sample at about 1Khz on a dual-core CPU and run an app for 10 seconds. An app that hogs the CPU should give us 20k samples, or 10k samples if it's pegged to a single core.

I coded this up in a cpu.d DTrace script and sampled Firefox. Apparently, Firefox only gets ~1700 samples on the CPU or 1.7s so its first 10 seconds of life are spent doing something else, e.g. disk IO.

We already know that Firefox is slow to start up but this type of sampling neatly points the finger in the right direction. Props to Brendan Gregg for teaching me how to fish!

What kind of IO does Firefox do upon startup, though? I find the output from iosnoop a bit confusing so I whipped up a version of my own that prints just disk access times, disk operation deltas, block size and file name accessed.

The script samples Firefox during the first 20 seconds of its life and the output from ./cold.sh io.d looks like this:

DELTA      DTIME      D    SIZE PATHNAME
1399       1407       R    4096 ??/dtrace/libdtrace_dyld.dylib
1141       1145       R    8192 ??/dtrace/libdtrace_dyld.dylib
1301       1305       R    4096 ??/MacOS/XUL
1701       1705       R    4096 ??/MacOS/XUL
11081      685        R    4096 ??/MacOS/libmozjs.dylib
1989       2253       R   36864 ??/MacOS/libmozjs.dylib
1768       1894       R   24576 ??/MacOS/libmozjs.dylib
27111      2135       R  200704 ??/MacOS/XUL
1411       1134       R    8192 ??/MacOS/libxpcom.dylib
1784       1968       R    4096 ??/MacOS/libplds4.dylib
2383       464        R    4096 ??/MacOS/libxpcom.dylib
2886       456        R    4096 ??/MacOS/libxpcom.dylib
1431       732        R    4096 ??/MacOS/libplds4.dylib
2640       706        R    4096 ??/MacOS/libnspr4.dylib
3092       484        R    4096 ??/MacOS/libnspr4.dylib
...

I also have a version that rolls disk operations by file name and read/write op. It also samples during 20 seconds and outputs something like this:

DELTA      DTIME         SIZE D PATHNAME
307        311           4096 R ??/en_US.ISO8859-1/LC_TIME
437        441           4096 R ??/pref/firefox-branding.js
439        443           4096 R ??/su3x40q6.2/extensions.cache
441        445           4096 R ??/en_US.ISO8859-1/LC_NUMERIC
640        644           4096 R ??/en_US.ISO8859-1/LC_MONETARY
643        648           4096 R ??/chrome/browser.manifest
644        650           4096 R ??/la_LN.US-ASCII/LC_COLLATE
645        650           4096 R ??/Firefox/profiles.ini
646        650           4096 R ??/chrome/en-US.manifest
...

All timings are in microseconds and specific to my Apple 256Gb SSD.

There's something else that I discovered during my snooping around with io.d. Compare the first 20 seconds of the life of Safari and the life of Firefox.

Basically, all the shared libraries used by Safari are pulled in from the dynamic library shared cache. Safari uses mostly system frameworks, e.g.

DYLD_PRINT_LIBRARIES_POST_LAUNCH=1 /Applications/Safari.app/Contents/MacOS/Safari 

dyld: loaded: /System/Library/CoreServices/RawCamera.bundle/Contents/MacOS/RawCamera
dyld: loaded: /System/Library/PrivateFrameworks/Shortcut.framework/Versions/A/Shortcut
dyld: loaded: /System/Library/PrivateFrameworks/HelpData.framework/Versions/A/HelpData
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCSync.A.dylib
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCGATS.A.dylib
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libRIP.A.dylib
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCGXCoreImage.A.dylib

whereas Firefox uses a whole lot more custom shared libraries, e.g.

DYLD_PRINT_LIBRARIES_POST_LAUNCH=1 ./Minefield.app/Contents/MacOS/firefox-bin -no-remote -foreground -P 2

dyld: loaded: /System/Library/CoreServices/RawCamera.bundle/Contents/MacOS/RawCamera
dyld: loaded: /System/Library/PrivateFrameworks/Shortcut.framework/Versions/A/Shortcut
dyld: loaded: /System/Library/PrivateFrameworks/HelpData.framework/Versions/A/HelpData
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCSync.A.dylib
dyld: loaded: 
/System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCGATS.A.dylib
dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libRIP.A.dylib

dyld: loaded: /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/ATS.framework/Versions/A/Resources/ATSHI.dylib
dyld: loaded: /Library/Internet Plug-Ins/QuickTime Plugin.plugin/Contents/MacOS/QuickTime Plugin
dyld: loaded: /System/Library/QuickTime/QuickTimeComponents.component/Contents/MacOS/QuickTimeComponents
dyld: loaded: /System/Library/Frameworks/AGL.framework/Versions/A/AGL
dyld: loaded: /System/Library/PrivateFrameworks/CoreAUC.framework/Versions/A/CoreAUC

dyld: loaded: /Users/joelr/Work/mozilla/startup/Minefield.app/Contents/MacOS/components/libbrowserdirprovider.dylib
dyld: loaded: /Users/joelr/Work/mozilla/startup/Minefield.app/Contents/MacOS/components/libbrowsercomps.dylib
dyld: loaded: /Users/joelr/Work/mozilla/startup/./Minefield.app/Contents/MacOS/libnssdbm3.dylib
dyld: loaded: /Users/joelr/Work/mozilla/startup/./Minefield.app/Contents/MacOS/libfreebl3.dylib
dyld: loaded: /Users/joelr/Work/mozilla/startup/Minefield.app/Contents/MacOS/libnssckbi.dylib
dyld: unloaded: /Users/joelr/Work/mozilla/startup/Minefield.app/Contents/MacOS/libnssckbi.dylib

I separated the list of libraries loaded by Firefox into three groups: same libraries as Safari, other system frameworks, custom libraries.

What needs to be done to make Firefox use the dynamic library shared cache as aggressively as Safari?

Another puzzling bit involves the difference between Safari libraries loaded by dyld (above) and the list of libraries that Safari is linked against, e.g.

otool -L  /Applications/Safari.app/Contents/MacOS/Safari 

	/System/Library/PrivateFrameworks/CrashReporterSupport.framework/Versions/A/CrashReporterSupport
	/System/Library/Frameworks/Cocoa.framework/Versions/A/Cocoa
	/System/Library/Frameworks/Carbon.framework/Versions/A/Carbon
	/System/Library/Frameworks/WebKit.framework/Versions/A/WebKit
	/System/Library/Frameworks/AddressBook.framework/Versions/A/AddressBook
	/System/Library/Frameworks/Security.framework/Versions/A/Security
	/System/Library/Frameworks/SystemConfiguration.framework/Versions/A/SystemConfiguration
	/System/Library/Frameworks/SecurityFoundation.framework/Versions/A/SecurityFoundation
	/System/Library/Frameworks/SecurityInterface.framework/Versions/A/SecurityInterface
	/System/Library/PrivateFrameworks/SyndicationUI.framework/Versions/A/SyndicationUI
	/System/Library/Frameworks/JavaScriptCore.framework/Versions/A/JavaScriptCore
	/System/Library/Frameworks/IOKit.framework/Versions/A/IOKit
	/System/Library/Frameworks/Quartz.framework/Versions/A/Quartz
	/System/Library/Frameworks/OpenGL.framework/Versions/A/OpenGL
	/usr/lib/libicucore.A.dylib
	/usr/lib/libstdc++.6.dylib
	/usr/lib/libgcc_s.1.dylib
	/usr/lib/libSystem.B.dylib
	/System/Library/Frameworks/CoreServices.framework/Versions/A/CoreServices
	/usr/lib/libobjc.A.dylib
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation
	/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit
	/System/Library/Frameworks/ApplicationServices.framework/Versions/A/ApplicationServices
	/System/Library/Frameworks/Foundation.framework/Versions/C/Foundation
	/System/Library/Frameworks/QuartzCore.framework/Versions/A/QuartzCore

Does Safari lazily loading some frameworks? Why do I see OpenGL initializers run when I set DYLD_PRINT_INITIALIZERS then? The OpenGL framework does not appear to be loaded when Safari starts (dyld output above).

For the sake of comparing, here's the list of libraries that Firefox is linked against

otool -L ./Minefield.app/Contents/MacOS/firefox-bin./Minefield.app/Contents/MacOS/firefox-bin:

	/System/Library/Frameworks/Cocoa.framework/Versions/A/Cocoa
	@executable_path/XUL
	@executable_path/libmozjs.dylib
	@executable_path/libxpcom.dylib
	@executable_path/libplds4.dylib
	@executable_path/libplc4.dylib
	@executable_path/libnspr4.dylib
	/System/Library/Frameworks/Carbon.framework/Versions/A/Carbon
	/System/Library/Frameworks/CoreAudio.framework/Versions/A/CoreAudio
	/System/Library/Frameworks/AudioToolbox.framework/Versions/A/AudioToolbox
	/System/Library/Frameworks/AudioUnit.framework/Versions/A/AudioUnit
	/System/Library/Frameworks/AddressBook.framework/Versions/A/AddressBook
	/usr/lib/libstdc++.6.dylib 
	/usr/lib/libgcc_s.1.dylib
	/usr/lib/libSystem.B.dylib

as well as the list of libraries for XUL

otool -L ./Minefield.app/Contents/MacOS/XUL

	@executable_path/XUL 
	/System/Library/Frameworks/Cocoa.framework/Versions/A/Cocoa
	@executable_path/libsqlite3.dylib
	@executable_path/libmozjs.dylib
	@executable_path/libsmime3.dylib
	@executable_path/libssl3.dylib
	@executable_path/libnss3.dylib
	@executable_path/libnssutil3.dylib
	@executable_path/libsoftokn3.dylib 
	/usr/lib/libcups.2.dylib
	@executable_path/libplds4.dylib
	@executable_path/libplc4.dylib
	@executable_path/libnspr4.dylib
	/System/Library/Frameworks/SystemConfiguration.framework/Versions/A/SystemConfiguration
	/System/Library/Frameworks/QuickTime.framework/Versions/A/QuickTime
	/System/Library/Frameworks/IOKit.framework/Versions/A/IOKit
	/usr/lib/libcrypto.0.9.7.dylib
	/System/Library/Frameworks/Carbon.framework/Versions/A/Carbon 
	/System/Library/Frameworks/CoreAudio.framework/Versions/A/CoreAudio
	/System/Library/Frameworks/AudioToolbox.framework/Versions/A/AudioToolbox
	/System/Library/Frameworks/AudioUnit.framework/Versions/A/AudioUnit
	/System/Library/Frameworks/AddressBook.framework/Versions/A/AddressBook
	/usr/lib/libstdc++.6.dylib
	/usr/lib/libgcc_s.1.dylib
	/usr/lib/libSystem.B.dylib
	/System/Library/Frameworks/CoreServices.framework/Versions/A/CoreServices
	/usr/lib/libobjc.A.dylib
	/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation
	/System/Library/Frameworks/AppKit.framework/Versions/C/AppKit
	/System/Library/Frameworks/ApplicationServices.framework/Versions/A/ApplicationServices
	/System/Library/Frameworks/Foundation.framework/Versions/C/Foundation

It turns out that DYLD_PRINT_LIBRARIES=1 is the way to show libraries loaded by dyld before a program's entry point (main) whereas DYLD_PRINT_LIBRARIES_POST_LAUNCH=1 will show libraries loaded afterwards, e.g. using dlopen or NSBundle.

August 25, 2009

Created a static probe that fires first thing in XRE_main and updated my DTrace scripts to use it.

pid$target::function:entry probes are very slow since DTrace may have to search thousands of functions. All that search time skews elapsed time reported by timestamp. USDT (static) probes are just a few NOP instructions in the code that get fixed up by DTrace as needed so they work much faster.

August 24, 2009

Startup time is measured from the entry to XRE_main to the return of the BrowserStartup JS function. It takes a good bit of time but nothing compared to the time elapsed from the start of Firefox to the call to XRE_main.

According to my static-init.d script, the static initialization time can be ignored. I'm recording the library name and then timing the following call to ImageLoader::runInitializers in dyld. The cumulative time is too small to be of essence, though.

0.000053548s for /System/Library/Frameworks/Carbon.framework/Frameworks/HIToolbox.framework/Versions/A/HIToolbox
0.000053732s for /Users/joelr/Work/mozilla/startup/./Minefield.app/Contents/MacOS/libsoftokn3.dylib
0.000069234s for /System/Library/PrivateFrameworks/Shortcut.framework/Versions/A/Shortcut
0.000070455s for /Users/joelr/Work/mozilla/startup/MinefieldRelease.app/Contents/MacOS/libnssckbi.dylib
0.000072754s for /Users/joelr/Work/mozilla/startup/MinefieldRelease.app/Contents/MacOS/components/libbrowsercomps.dylib
0.000073443s for /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/ATS.framework/Versions/A/Resources/ATSHI.dylib
0.000074363s for /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCSync.A.dylib
0.000075845s for /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libCGATS.A.dylib
0.000076892s for /System/Library/Frameworks/ApplicationServices.framework/Versions/A/Frameworks/CoreGraphics.framework/Versions/A/Resources/libRIP.A.dylib
0.000089767s for /Users/joelr/Work/mozilla/startup/./Minefield.app/Contents/MacOS/libnssdbm3.dylib
0.000094390s for /Users/joelr/Work/mozilla/startup/./Minefield.app/Contents/MacOS/libfreebl3.dylib
0.000100462s for /System/Library/Frameworks/CoreServices.framework/Versions/A/Frameworks/CarbonCore.framework/Versions/A/CarbonCore
0.000115375s for /System/Library/Frameworks/Carbon.framework/Versions/A/Frameworks/HIToolbox.framework/Versions/A/HIToolbox
0.001161267s for /Users/joelr/Work/mozilla/startup/MinefieldRelease.app/Contents/MacOS/components/libbrowserdirprovider.dylib
---------------
= 0.002181527s

Initialization: 42.986413480s
Startup       : 7.015292701s
---------------
= 50.001706181s

Digging deeper...

August 21, 2009

Blogged.

My DTrace scripts live here. Use like this

sudo ./cold.sh static-init.d

Shark tips and tricks

Expanding the call tree

Alt-Click does it.

CHUD signposts on Snow Leopard

There are no CHUD header files on Snow Leopard. If you're only interest is in emitting signposts, the easiest thing for you to do is switch to the syscall method instead.  That'll also mean you won't have to link against the CHUD framework. The full details are in the Shark User Guide, but in brief:

int err = syscall(SYS_kdebug_trace, APPSDBG_CODE(DBG_MACH_CHUD, <your code number>) | <type>, arg1, arg2, arg3, arg4);

Types are DBG_FUNC_START, DBG_FUNC_END and DBG_FUNC_NONE (for point signposts).

Don't forget to include <sys/kdebug.h> and <sys/syscall.h> for the necessary macros and function.

DTrace tips and tricks

DTrace overhead and proper measuring technique

I'm still not done!

Function entry/return vs static probes

Q: I added a couple of static probes to Firefox to measure actual work done. I could have used a pid$target probe with a function name but work is done within an if statement, which is where I placed the static probes. I'm wondering about my use, though. Is the following significantly more efficient than pid$target::FunName:entry and return?

A: No, it's not significantly more efficient. Both function entry/return probes and USDT probes involve replacing an instruction in the stream with a trap instruction. The expense of the trap into the kernel is going to overwhelm any subtleties in handling between the two different types of probes. --Chad Mynhier

Combining scripts

I find it convenient to have separate DTrace scripts for various exit probes. This way I can avoid editing the main script whenever I want to stop sampling once 10 seconds go by or XRE_main is entered or the BrowserReturn JavaScript function returns.

It can be done like this

#!/bin/bash 

cmd="./Minefield.app/Contents/MacOS/firefox-bin -no-remote -foreground -P 2"
scripts=""

for i in $*; do scripts="$scripts -s $i"; done

sync && purge && dtrace -x dynvarsize=64m -x evaltime=exec -c "$cmd" -wZ $scripts

and then

./cold.sh startup.d stop-main.d 
Total: 11001.481323ms

or

./cold.sh startup.d stop-js.d 
Total: 7004.799264ms

My scripts can be found on GitHub.

No sudo

sudo chmod u+s `which dtrace`

You can now run dtrace as yourself. Enjoy!

timestamp vs vtimestamp

vtimestamp measures CPU time of the current thread, excluding IO and DTrace overhead. timestamp can still be used for deltas but the goal is to use as few pid$target probes as possible as they affect timestamp when dtrace has to switch between kernel and userland. io and syscall providers are fast and run in the kernel.

Invalid address

Have you seen this kind of error before?

dtrace: error on enabled probe ID 27 (ID 22130: pid34547:libSystem.B.dylib:dlopen:entry): invalid address (0x2ac204) in action #1 at DIF offset 28
dtrace: error on enabled probe ID 2 (ID 22782: pid34547:dyld:dlopen:entry): invalid address (0x2ac204) in action #1 at DIF offset 28

More likely than not, you are using copyinstr on memory that hasn't been paged in yet. Try saving the pointer on entry and doing the copying on return or later. Italic text