Closed Bug 799638 Opened 7 years ago Closed 7 years ago

Need a startup-profiling mode

Categories

(Core :: Gecko Profiler, defect)

x86_64
Windows 7
defect
Not set

Tracking

()

RESOLVED FIXED
mozilla19
Tracking Status
b2g18 ? affected

People

(Reporter: taras.mozilla, Assigned: BenWa)

References

Details

Attachments

(3 files, 5 obsolete files)

< 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.
Blocks: 799640
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.
I made some progress on this today but for some reason 'sessionstore-windows-restored' doesn't fire and I can't find out why.
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.
(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?
no luck :(
(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.
(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
(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
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.
Neither of these options work. I'm giving up until I can steal some of Ehsan time to help me debug this.
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.
(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.
Not strictly needed but giving better stacks.
Assignee: nobody → bgirard
Status: NEW → ASSIGNED
Attachment #671015 - Flags: review?(ehsan)
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.
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 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.
Attachment #671015 - Flags: review?(ehsan) → review+
(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.  :-)
(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?
(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
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
(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.
Attached patch save markers (obsolete) — Splinter Review
This is from dynamic marker bug which is stalled on the breakpad integration. We can land this subset now.
Attachment #671139 - Flags: review?(ehsan)
Attached patch add startup timeline markers (obsolete) — Splinter Review
Attachment #671140 - Flags: review?(taras.mozilla)
Attached patch save markers (obsolete) — Splinter Review
Rename markers -> marker to be consistent with the old profile format. This way we support markers from old profiles.
Attachment #671139 - Attachment is obsolete: true
Attachment #671139 - Flags: review?(ehsan)
Attachment #671141 - Flags: review?(ehsan)
Attachment #671141 - Flags: review?(ehsan) → review+
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.
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 on attachment 671140 [details] [diff] [review]
add startup timeline markers

lovely hack
Attachment #671140 - Flags: review?(taras.mozilla) → review+
(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
(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
Target Milestone: --- → mozilla19
(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
Target Milestone: mozilla19 → ---
(BTW, you don't need to set the target milestone when landing on inbound anymore)
Attached patch save markersSplinter Review
Argg. I used the wrong command when exporting the patch and missed a hunk :(
Attachment #671154 - Flags: review?(ehsan)
Attachment #671154 - Flags: review?(ehsan) → review+
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.
Depends on: 785507
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.
Attachment #671140 - Flags: review-
Attached patch add startup timeline markers (obsolete) — Splinter Review
Attachment #671140 - Attachment is obsolete: true
Attachment #671141 - Attachment is obsolete: true
Attachment #681693 - Flags: review?(mh+mozilla)
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.
Attachment #681693 - Flags: review?(mh+mozilla) → review+
Attached patch add startup timeline markers (obsolete) — Splinter Review
Attachment #681693 - Attachment is obsolete: true
Attachment #682058 - Flags: review+
Attachment #682058 - Attachment is obsolete: true
Attachment #682065 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/bbd553b9d234
Status: ASSIGNED → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla19
Can we get this onto b2g18? It's necessary to be able to compare 1.1 and 1.2+ profiles.
blocking-b2g: --- → leo?
tracking-b2g18: --- → ?
b2g18 will only benefit from 'save markers' patch and MAYBE 'add startup timeline markers'. Feel free to rebase & request uplift.
(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?
(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.
(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?
Flags: needinfo?(mhabicher)
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
Attachment #671154 - Flags: approval-mozilla-b2g18?
Mike - I need an answer to comment 48 to be able to figure out a triage decision on this bug.
(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.
Flags: needinfo?(mhabicher)
blocking-b2g: leo? → ---
Attachment #671154 - Flags: approval-mozilla-b2g18? → approval-mozilla-b2g18-
You need to log in before you can comment on or make changes to this bug.