675233 - Profile: break up startup into a timeline

Status: RESOLVED WONTFIX

(Firefox for Android Graveyard :: General, defect, P1)

Description

[Benjamin Stover (:stechz)]

This patch allows you to see at what point in startup a component has been initialized. You might find this useful for figuring out the bottlenecks in our startup code.

Comment 1

[Benjamin Stover (:stechz)]

Attachment: Profiling: show time elapsed after main when a new component is initialized

Comment 2

[Benjamin Stover (:stechz)]

Attachment: Script for finding largest time delays

This is just an HTML file that can read the output of the above patch and figure out where the biggest time delays are.

Comment 3

[Benjamin Stover (:stechz)]

Attachment: Results for my Nexus S

Here are the results for my phone, on "cold startup." Here is how I got these results:
* Load your Fennec and launch adb logcat
* Open Firefox 5 and load http://tbpl.mozilla.org/?tree=Firefox :)
* In logcat, you should see that the Fennec process is killed. If not, load more tabs!
* Hold down home button, select Fennec.
* The results will be in adb logcat

These results are with some of my startup patches that delay SQLite loading as long as possible, and it uses a very small XUL file that then loads the browser.

Some noticeable hotspots from this:
* something between gfx/info and gfx/init takes 224ms
* addons-integration seems to be taking 187ms

Comment 4

[Benjamin Stover (:stechz)]

Attachment: Script for finding largest time delays

New script uses previous event instead of next event in difference finding, which tends to be more useful. Also, converts microseconds to milliseconds.

Comment 5

[Benjamin Stover (:stechz)]

Attachment: WIP: Enable function timers for Android

Comment 6

[Benjamin Stover (:stechz)]

Attachment: Cold restart

HTML output from the parser uploaded here:
https://github.com/stechz/Mobile-Firefox-Startup-Profiler

I'm not 100% confident in these numbers, but they can be verified by looking at the logs. Some interesting notes:
* Total time to first paint was just over 10 seconds
* About a fifth of the time was before main
* XPTI parsing took 476ms
* The recorded JS running/parsing took 1197ms
* XUL parsing is accidentally missing from the log output of this patch but looks to be about 582ms
* The recorded layout stuff: 468ms + 507ms + 188ms

Comment 7

[Benjamin Stover (:stechz)]

Hm, not sure where the XUL parsing went. There is no record of nsXULPrototypeDocument::Read at all. This patch ignores any logs off the main thread, so perhaps it is conditionally read async?

Comment 8

[(no longer active)]

with functiontimers, you should be able to look at the vtable pointer for the runnables processed on the event queue to get a better understanding of what events take the longest to process.

Comment 9

[Jeff Muizelaar [:jrmuizel]]

I had a look at the example:

This log hunk gets called gfx loading fonts and is assigned a value of 152ms. However,
it looks gfxPlatformFontList::Init only takes 38ms. What's going on here?


I/Gecko ( 7202): [default 4439.00] > ( 10) |?MINMS virtual nsresult nsComponentManagerImpl::GetServiceByContractID(const char*, const nsIID&, void**) (line 1649) (contractid: @mozilla.org/gfx/info;1) I/Gecko ( 7202): [default 4439.00] > ( 11) |?MINMS virtual nsresult nsComponentManagerImpl::CreateInstanceByContractID(const char*, nsISupports*, const nsIID&, void**) (line 1253) (contractid: @mozilla.org/gfx/info;1) I/Gecko ( 7202): [default 4440.00] < ( 11) |<MINMS 1.00 ms ( 1.00 ms total) - virtual nsresult nsComponentManagerImpl::CreateInstanceByContractID(const char*, nsISupports*, const nsIID&, void**) (line 1253) (contractid: @mozilla.org/gfx/info;1) I/Gecko ( 7202): [default 4440.00] < ( 10) |<MINMS 1.00 ms ( 1.00 ms total) - virtual nsresult nsComponentManagerImpl::GetServiceByContractID(const char*, const nsIID&, void**) (line 1649) (contractid: @mozilla.org/gfx/info;1) I/Gecko ( 7202): [default 4543.00] > ( 10) |static nsresult gfxPlatformFontList::Init() (line 67) I/Gecko ( 7202): [default 4581.00] < ( 10) | 38.00 ms ( 38.00 ms total) - static nsresult gfxPlatformFontList::Init() (line 67) I/Gecko ( 7202): [default 4591.00] > ( 10) |?MINMS virtual nsresult nsComponentManagerImpl::CreateInstanceByContractID(const char*, nsISupports*, const nsIID&, void**) (line 1253) (contractid: @mozilla.org/gfx/init;1)

Comment 10

[BMO Automation]

Closing all opened bug in a graveyard component