Last Comment Bug 799638 - Need a startup-profiling mode
: Need a startup-profiling mode
Status: RESOLVED FIXED
:
Product: Core
Classification: Components
Component: Gecko Profiler (show other bugs)
: unspecified
: x86_64 Windows 7
: -- normal with 1 vote (vote)
: mozilla19
Assigned To: Benoit Girard (:BenWa)
:
Mentors:
Depends on: 785507
Blocks: 799640
  Show dependency treegraph
 
Reported: 2012-10-09 12:31 PDT by (dormant account)
Modified: 2013-12-27 14:26 PST (History)
16 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
?
affected


Attachments
use stackwalk on win/mac (1.01 KB, patch)
2012-10-12 19:22 PDT, Benoit Girard (:BenWa)
ehsan: review+
Details | Diff | Review
save markers (2.47 KB, patch)
2012-10-13 14:28 PDT, Benoit Girard (:BenWa)
no flags Details | Diff | Review
add startup timeline markers (1.18 KB, patch)
2012-10-13 14:29 PDT, Benoit Girard (:BenWa)
taras.mozilla: review+
mh+mozilla: review-
Details | Diff | Review
save markers (1.53 KB, patch)
2012-10-13 14:36 PDT, Benoit Girard (:BenWa)
ehsan: review+
Details | Diff | Review
save markers (2.46 KB, patch)
2012-10-13 18:31 PDT, Benoit Girard (:BenWa)
ehsan: review+
bajaj.bhavana: approval‑mozilla‑b2g18-
Details | Diff | Review
add startup timeline markers (1.24 KB, patch)
2012-11-14 14:01 PST, Benoit Girard (:BenWa)
mh+mozilla: review+
Details | Diff | Review
add startup timeline markers (6.78 KB, patch)
2012-11-15 10:25 PST, Benoit Girard (:BenWa)
bgirard: review+
Details | Diff | Review
add startup timeline markers (1.57 KB, patch)
2012-11-15 10:41 PST, Benoit Girard (:BenWa)
bgirard: review+
Details | Diff | Review

Description (dormant account) 2012-10-09 12:31:31 PDT
< 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) 2012-10-09 12:56:38 PDT
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) 2012-10-09 19:09:40 PDT
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) 2012-10-10 10:13:15 PDT
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 :Ehsan Akhgari (busy, don't ask for review please) 2012-10-10 10:32:39 PDT
(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) 2012-10-10 18:09:27 PDT
no luck :(
Comment 6 :Ehsan Akhgari (busy, don't ask for review please) 2012-10-11 15:58:53 PDT
(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) 2012-10-11 16:29:47 PDT
(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) 2012-10-11 16:33:08 PDT
(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) 2012-10-11 16:47:35 PDT
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) 2012-10-12 08:44:19 PDT
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) 2012-10-12 11:56:39 PDT
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) 2012-10-12 18:48:10 PDT
(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) 2012-10-12 19:22:24 PDT
Created attachment 671015 [details] [diff] [review]
use stackwalk on win/mac

Not strictly needed but giving better stacks.
Comment 14 Benoit Girard (:BenWa) 2012-10-12 19:25:10 PDT
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) 2012-10-12 19:30:53 PDT
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 :Ehsan Akhgari (busy, don't ask for review please) 2012-10-12 21:33:16 PDT
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 :Ehsan Akhgari (busy, don't ask for review please) 2012-10-12 21:34:06 PDT
(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) 2012-10-12 22:13:03 PDT
(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) 2012-10-12 22:37:31 PDT
(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) 2012-10-13 07:37:20 PDT
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) 2012-10-13 07:51:55 PDT
(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) 2012-10-13 14:28:53 PDT
Created attachment 671139 [details] [diff] [review]
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) 2012-10-13 14:29:45 PDT
Created attachment 671140 [details] [diff] [review]
add startup timeline markers
Comment 24 Benoit Girard (:BenWa) 2012-10-13 14:36:23 PDT
Created attachment 671141 [details] [diff] [review]
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) 2012-10-13 14:44:10 PDT
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) 2012-10-13 15:25:19 PDT
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) 2012-10-13 16:57:34 PDT
Comment on attachment 671140 [details] [diff] [review]
add startup timeline markers

lovely hack
Comment 28 (dormant account) 2012-10-13 17:13:39 PDT
(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) 2012-10-13 17:15:22 PDT
(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 31 Ryan VanderMeulen [:RyanVM] 2012-10-13 18:23:59 PDT
(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] 2012-10-13 18:24:26 PDT
(BTW, you don't need to set the target milestone when landing on inbound anymore)
Comment 33 Benoit Girard (:BenWa) 2012-10-13 18:31:17 PDT
Created attachment 671154 [details] [diff] [review]
save markers

Argg. I used the wrong command when exporting the patch and missed a hunk :(
Comment 36 Benoit Girard (:BenWa) 2012-10-16 11:08:21 PDT
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] 2012-11-07 22:56:18 PST
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) 2012-11-14 14:01:37 PST
Created attachment 681693 [details] [diff] [review]
add startup timeline markers
Comment 39 Mike Hommey [:glandium] 2012-11-14 22:12:46 PST
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) 2012-11-15 10:25:21 PST
Created attachment 682058 [details] [diff] [review]
add startup timeline markers
Comment 41 Benoit Girard (:BenWa) 2012-11-15 10:41:27 PST
Created attachment 682065 [details] [diff] [review]
add startup timeline markers
Comment 43 Ryan VanderMeulen [:RyanVM] 2012-11-15 17:41:50 PST
https://hg.mozilla.org/mozilla-central/rev/bbd553b9d234
Comment 44 Mike Habicher [:mikeh] (high bugzilla latency) 2013-09-19 11:02:18 PDT
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) 2013-09-19 11:05:49 PDT
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] 2013-09-19 15:19:34 PDT
(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] 2013-09-19 15:20:30 PDT
(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] 2013-09-20 10:10:52 PDT
(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) 2013-09-24 13:45:23 PDT
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] 2013-09-24 16:10:22 PDT
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) 2013-09-25 12:26:56 PDT
(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.

Note You need to log in before you can comment on or make changes to this bug.