799638 - Need a startup-profiling mode

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect)

Description

[(dormant account)]

< BenWa> We could have the profiler have an option to 'Profile startup' where it restarts firefox while profiling it and listens for session-restore

The listener would stop the profiler, open cleopatra.
Note the profiler must allocate a big enough buffer to record all of startup.

This would be useful to profiler unusually slow startups seen in the wild.

Comment 1

[Benoit Girard (:BenWa)]

This isn't hard to do, maybe 2 hours of work.

We can use nsIAppStartup to trigger a restart and set MOZ_PROFILER_STARTUP and have the extension ready to dump the profile when we fire the session-restored event.

Comment 2

[Benoit Girard (:BenWa)]

I made some progress on this today but for some reason 'sessionstore-windows-restored' doesn't fire and I can't find out why.

Comment 3

[Benoit Girard (:BenWa)]

Here's a sample build:
http://people.mozilla.com/~bgirard/geckoprofiler_startup.xpi

1) Install
2) In the profiler toolbar hit 'Shutdown+Startup'
3) On restart a tab will open with a profile of startup. Note this is when the extensions are loaded not on session restore because of Comment 2.

Comment 4

[(no longer active)]

(In reply to comment #2)
> I made some progress on this today but for some reason
> 'sessionstore-windows-restored' doesn't fire and I can't find out why.

Do you get sessionstore-browser-state-restored by any chance?

Comment 5

[Benoit Girard (:BenWa)]

no luck :(

Comment 6

[(no longer active)]

(In reply to comment #5)
> no luck :(

Then you're probably hitting a sessionstore bug, since you're supposed to get one or the other I believe.  Please file it and CC ttaubert on it.

Comment 7

[(dormant account)]

(In reply to Ehsan Akhgari [:ehsan] from comment #6)
> (In reply to comment #5)
> > no luck :(
> 
> Then you're probably hitting a sessionstore bug, since you're supposed to
> get one or the other I believe.  Please file it and CC ttaubert on it.

or a jetpack bug

Comment 8

[(dormant account)]

(In reply to Ehsan Akhgari [:ehsan] from comment #6)
> (In reply to comment #5)
> > no luck :(
> 
> Then you're probably hitting a sessionstore bug, since you're supposed to
> get one or the other I believe.  Please file it and CC ttaubert on it.

try  browser-delayed-startup-finished, looks like there are some situations when sessionstore-windows-restored does not fire, ie bug 645428

Comment 9

[Benoit Girard (:BenWa)]

The jetpack bug is a good theory. I could bypass their observer wrapper and try to listen to it directly. I'll try 'browser-delayed-startup-finished' as well.

Comment 10

[Benoit Girard (:BenWa)]

Neither of these options work. I'm giving up until I can steal some of Ehsan time to help me debug this.

Comment 11

[Benoit Girard (:BenWa)]

We looked at it and turns out that 'sessionstore-windows-restored' and related events fire before the extension is loaded so we have no chance of getting them. I think it's acceptable to dump the profile once the addon is loaded.

Comment 12

[(dormant account)]

(In reply to Benoit Girard (:BenWa) from comment #11)
> We looked at it and turns out that 'sessionstore-windows-restored' and
> related events fire before the extension is loaded so we have no chance of
> getting them. I think it's acceptable to dump the profile once the addon is
> loaded.

Yup. I thought normal restartless extensions call bootstrap before UI is shown, but maybe I'm misremembering.

Comment 13

[Benoit Girard (:BenWa)]

Attachment: use stackwalk on win/mac

Not strictly needed but giving better stacks.

Comment 14

[Benoit Girard (:BenWa)]

Deployed extension changes but I haven't tested on windows so if someone could be so kind to let me know if I need to back it out :):

https://github.com/bgirard/Gecko-Profiler-Addon/commit/960dc4311b2e0ed0db572a6939c9d34bd4700a18

Make sure you're on the github update channel rather than amo.

Comment 15

[Benoit Girard (:BenWa)]

Here's my sample startup profile without the above patch:

http://people.mozilla.com/~bgirard/cleopatra/?report=7dc0c1f200388afc1a2218572d6dfb94eb58d31c

Startup time:  < 1400 ms
Addon manager:     72 ms
io.js:            409 ms
session storage:  288 ms

Comment 16

[(no longer active)]

Comment on attachment 671015 [details] [diff] [review]
use stackwalk on win/mac

Review of attachment 671015 [details] [diff] [review]:
-----------------------------------------------------------------

r=me if you use mozilla::ArrayLength.

Comment 17

[(no longer active)]

(In reply to comment #14)
> Deployed extension changes but I haven't tested on windows so if someone could
> be so kind to let me know if I need to back it out :):

If no-one gets back to you, let's test this on Windows on Monday.  :-)

Comment 18

[(dormant account)]

(In reply to Benoit Girard (:BenWa) from comment #15)
> Here's my sample startup profile without the above patch:
> 
> http://people.mozilla.com/~bgirard/cleopatra/
> ?report=7dc0c1f200388afc1a2218572d6dfb94eb58d31c
> 
> Startup time:  < 1400 ms
> Addon manager:     72 ms
> io.js:            409 ms
> session storage:  288 ms

how do you attribute times to these? is this just a sample based on percentage next to stack * total time?

I noticed '*' doesn't do anything anymore, but that was broken before this build.

I tried the extension on windows, seem to work: http://people.mozilla.com/~bgirard/cleopatra/?report=00e4544949a48f739762aec1eeb083dcb7060360
Adblock is to blame for much overhead here(makes sense).

Can i ask for a feature request to show http://dxr.mozilla.org/mozilla-central/toolkit/components/startup/StartupTimeline.h.html on the timeline?

Comment 19

[(dormant account)]

(In reply to Taras Glek (:taras) from comment #18)
> (In reply to Benoit Girard (:BenWa) from comment #15)
> > Here's my sample startup profile without the above patch:
> > 
> > http://people.mozilla.com/~bgirard/cleopatra/
> > ?report=7dc0c1f200388afc1a2218572d6dfb94eb58d31c
> > 
> > Startup time:  < 1400 ms
> > Addon manager:     72 ms
> > io.js:            409 ms
> > session storage:  288 ms
> 
So if we can automate this & pretty it up(which we basically can), we have a powerful equivalent to IE startup self-diagnosis tool: http://www.howtogeek.com/wp-content/uploads/2012/05/03_choose_addons_dialog.png

Comment 20

[Benoit Girard (:BenWa)]

Markus sent me a pull request that handles this profile much better:
https://github.com/bgirard/cleopatra/pull/21

- Better at detecting non jetpack addons (AdBlock)
- Better at parsing the URLs
- Column for the icons

Comment 21

[Benoit Girard (:BenWa)]

(In reply to Taras Glek (:taras) from comment #18)
> (In reply to Benoit Girard (:BenWa) from comment #15)
> > Here's my sample startup profile without the above patch:
> > 
> > http://people.mozilla.com/~bgirard/cleopatra/
> > ?report=7dc0c1f200388afc1a2218572d6dfb94eb58d31c
> > 
> > Startup time:  < 1400 ms
> > Addon manager:     72 ms
> > io.js:            409 ms
> > session storage:  288 ms
> 
> how do you attribute times to these? is this just a sample based on
> percentage next to stack * total time?
> 

I did then by hand for now based on sample * interval. This is accurate if all the samples are clustered in one block and the real interval matches the expected interval.

> I noticed '*' doesn't do anything anymore, but that was broken before this
> build.

fixed

> 
> I tried the extension on windows, seem to work:
> http://people.mozilla.com/~bgirard/cleopatra/
> ?report=00e4544949a48f739762aec1eeb083dcb7060360
> Adblock is to blame for much overhead here(makes sense).

Same on my side. We should contact Adblock and see if they can improve or delay some work.

> 
> Can i ask for a feature request to show
> http://dxr.mozilla.org/mozilla-central/toolkit/components/startup/
> StartupTimeline.h.html on the timeline?

It's easy to add static marker, just need to add them to the UI in a nice way.

Comment 22

[Benoit Girard (:BenWa)]

Attachment: save markers

This is from dynamic marker bug which is stalled on the breakpad integration. We can land this subset now.

Comment 23

[Benoit Girard (:BenWa)]

Attachment: add startup timeline markers

Comment 24

[Benoit Girard (:BenWa)]

Attachment: save markers

Rename markers -> marker to be consistent with the old profile format. This way we support markers from old profiles.

Comment 25

[Benoit Girard (:BenWa)]

Here's a profile collected with the above patches that include the timeline events:
http://people.mozilla.com/~bgirard/cleopatra/?report=22511879a2b3affb25e6c7efdabb856fdd2a2d31

I'll be deploying an update to Cleopatra to show markers text when it's ready.

Comment 26

[Benoit Girard (:BenWa)]

I added markers to the canvas, you can try it with the above profile. It looks really terrible but it's usable at least. I'm sure someone will be motivated to improve it.

Comment 27

[(dormant account)]

Comment on attachment 671140 [details] [diff] [review]
add startup timeline markers

lovely hack

Comment 28

[(dormant account)]

(In reply to Benoit Girard (:BenWa) from comment #26)
> I added markers to the canvas, you can try it with the above profile. It
> looks really terrible but it's usable at least. I'm sure someone will be
> motivated to improve it.

Would be nice to have labels atleast, I don't mind the pink markers

Comment 29

[(dormant account)]

(In reply to Benoit Girard (:BenWa) from comment #25)
> 
> I'll be deploying an update to Cleopatra to show markers text when it's
> ready.
Nevermind my previous comment, looks good

Comment 30

[Benoit Girard (:BenWa)]

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/632ce3e7d3ef
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/2a8fef2bd228
remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/a57ade621efb

Comment 31

[Ryan VanderMeulen [:RyanVM]]

(In reply to Taras Glek (:taras) from comment #29)
> Nevermind my previous comment, looks good

The tree disagrees. Backed out.
https://hg.mozilla.org/integration/mozilla-inbound/rev/dfbaea0d50d1

https://tbpl.mozilla.org/php/getParsedLog.php?id=16093880&tree=Mozilla-Inbound

TableTicker.cpp
/usr/bin/ccache /tools/gcc-4.5-0moz3/bin/g++ -o TableTicker.o -c -I../../dist/stl_wrappers -I../../dist/system_wrappers -include /builds/slave/m-in-lnx/build/config/gcc_hidden.h -DMOZ_GLUE_IN_PROGRAM -DXPCOM_TRANSLATE_NSGM_ENTRY_POINT=1 -DMOZILLA_INTERNAL_API -D_IMPL_NS_COM -DEXPORT_XPT_API -DEXPORT_XPTC_API -D_IMPL_NS_GFX -D_IMPL_NS_WIDGET -DIMPL_XREAPI -DIMPL_NS_NET -DIMPL_THEBES  -DSTATIC_EXPORTABLE_JS_API -I/builds/slave/m-in-lnx/build/mozglue/linker -I/builds/slave/m-in-lnx/build/ipc/chromium/src  -I/builds/slave/m-in-lnx/build/tools/profiler -I. -I../../dist/include  -I/builds/slave/m-in-lnx/build/obj-firefox/dist/include/nspr -I/builds/slave/m-in-lnx/build/obj-firefox/dist/include/nss      -fPIC  -pedantic -Wall -Wpointer-arith -Woverloaded-virtual -Werror=return-type -Wtype-limits -Wempty-body -Wno-ctor-dtor-privacy -Wno-overlength-strings -Wno-invalid-offsetof -Wno-variadic-macros -Wcast-align -Wno-long-long -fno-exceptions -fno-strict-aliasing -fno-rtti -ffunction-sections -fdata-sections -fno-exceptions -std=gnu++0x -pthread -pipe  -DNDEBUG -DTRIMMED -g -Os -freorder-blocks -finline-limit=50 -fno-omit-frame-pointer    -DMOZILLA_CLIENT -include ../../mozilla-config.h -MD -MF .deps/TableTicker.o.pp  /builds/slave/m-in-lnx/build/tools/profiler/TableTicker.cpp
/builds/slave/m-in-lnx/build/obj-firefox/_virtualenv/bin/python /builds/slave/m-in-lnx/build/build/xpccheck.py \
	  /builds/slave/m-in-lnx/build \
	  /builds/slave/m-in-lnx/build/testing/xpcshell/xpcshell.ini \
	  /builds/slave/m-in-lnx/build/tools/profiler/tests
../../../tools/profiler/TableTicker.cpp: In member function 'JSObject* ThreadProfile::ToJSObject(JSContext*)':
../../../tools/profiler/TableTicker.cpp:329:48: error: no matching function for call to 'JSObjectBuilder::ArrayPush(JSObject*&, const char*&)'
../../../tools/profiler/JSObjectBuilder.h:73:8: note: candidates are: void JSObjectBuilder::ArrayPush(JSObject*, int) <near match>
../../../tools/profiler/JSObjectBuilder.h:89:8: note:                 void JSObjectBuilder::ArrayPush(JSObject*, JSObject*)
make[5]: Leaving directory `/builds/slave/m-in-lnx/build/obj-firefox/tools/profiler'
make[5]: *** [TableTicker.o] Error 1

Comment 32

[Ryan VanderMeulen [:RyanVM]]

(BTW, you don't need to set the target milestone when landing on inbound anymore)

Comment 33

[Benoit Girard (:BenWa)]

Attachment: save markers

Argg. I used the wrong command when exporting the patch and missed a hunk :(

Comment 34

[Benoit Girard (:BenWa)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/6886bd9090c3
https://hg.mozilla.org/integration/mozilla-inbound/rev/2d29c74b9c9c

Comment 35

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/6886bd9090c3
https://hg.mozilla.org/mozilla-central/rev/2d29c74b9c9c

Comment 36

[Benoit Girard (:BenWa)]

Sometimes we hang on loading the profile. This is because of bug 785507 where a URL doesn't exist aborts the script and doesn't let us catch the exception.

Comment 37

[Mike Hommey [:glandium]]

Comment on attachment 671140 [details] [diff] [review]
add startup timeline markers

Review of attachment 671140 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/components/startup/StartupTimeline.h
@@ +58,5 @@
>      return sStartupTimelineDesc[ev];
>    }
>  
>    static void Record(Event ev, PRTime when = PR_Now()) {
> +    SAMPLE_MARKER(Describe(ev));

We should not add a marker for events where a "when" value was given, because they will just be noise in the profile timeline.

Comment 38

[Benoit Girard (:BenWa)]

Attachment: add startup timeline markers

Comment 39

[Mike Hommey [:glandium]]

Comment on attachment 681693 [details] [diff] [review]
add startup timeline markers

Review of attachment 681693 [details] [diff] [review]:
-----------------------------------------------------------------

::: toolkit/components/startup/StartupTimeline.h
@@ +66,1 @@
>    static void Record(Event ev, PRTime when = PR_Now()) {

You might as well remove the = PR_Now() here.

Comment 40

[Benoit Girard (:BenWa)]

Attachment: add startup timeline markers

Comment 41

[Benoit Girard (:BenWa)]

Attachment: add startup timeline markers

Comment 42

[Benoit Girard (:BenWa)]

https://hg.mozilla.org/integration/mozilla-inbound/rev/bbd553b9d234

Comment 43

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/bbd553b9d234

Comment 44

[Mike Habicher [:mikeh] (high bugzilla latency)]

Can we get this onto b2g18? It's necessary to be able to compare 1.1 and 1.2+ profiles.

Comment 45

[Benoit Girard (:BenWa)]

b2g18 will only benefit from 'save markers' patch and MAYBE 'add startup timeline markers'. Feel free to rebase & request uplift.

Comment 46

[Jason Smith [:jsmith]]

(In reply to Mike Habicher [:mikeh] from comment #44)
> Can we get this onto b2g18? It's necessary to be able to compare 1.1 and
> 1.2+ profiles.

That's probably a good idea. What's the risk assessment on these patches?

Comment 47

[Jason Smith [:jsmith]]

(In reply to Jason Smith [:jsmith] from comment #46)
> (In reply to Mike Habicher [:mikeh] from comment #44)
> > Can we get this onto b2g18? It's necessary to be able to compare 1.1 and
> > 1.2+ profiles.
> 
> That's probably a good idea. What's the risk assessment on these patches?

Although at the same time, we're past the point for allowing uplifts, so I'm not sure this will be allowed for uplift.

Comment 48

[Andrew Overholt [:overholt]]

(In reply to Mike Habicher [:mikeh] from comment #44)
> Can we get this onto b2g18? It's necessary to be able to compare 1.1 and
> 1.2+ profiles.

Milan and I just discussed this and are wondering if people doing 1.1-to-1.2 comparisons can just apply these patches locally.  Is that a viable option?

Comment 49

[Mike Habicher [:mikeh] (high bugzilla latency)]

Comment on attachment 671154 [details] [diff] [review]
save markers

NOTE: This flag is now for security issues only. Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): n/a
User impact if declined: unable to get profiler markers in b2g18 output, unable to compare marker output between v1.1 builds and later ones
Testing completed: I've been using this change in builds for over a week now
Risk to taking this patch (and alternatives if risky): minimal--code is only active if the profiler is started
String or UUID changes made by this patch: none

Comment 50

[Jason Smith [:jsmith]]

Mike - I need an answer to comment 48 to be able to figure out a triage decision on this bug.

Comment 51

[Mike Habicher [:mikeh] (high bugzilla latency)]

(In reply to Andrew Overholt [:overholt] from comment #48)
>
> (In reply to Mike Habicher [:mikeh] from comment #44)
>
> > Can we get this onto b2g18? It's necessary to be able to compare 1.1 and
> > 1.2+ profiles.
> 
> Milan and I just discussed this and are wondering if people doing 1.1-to-1.2
> comparisons can just apply these patches locally.  Is that a viable option?

Andrew, Jason: yeah, that's a viable option. I was thinking about this last night, and what I'll do is roll all of the disparate patches up into a single patch and attach it to a new bug; that way, if anyone needs to do 1.1-to-1.2 comparisons, s/he can just apply that patch and go.