The default bug view has changed. See this FAQ.

Need a startup-profiling mode

RESOLVED FIXED in mozilla19

Status

()

Core
Gecko Profiler
RESOLVED FIXED
5 years ago
3 years ago

People

(Reporter: (dormant account), Assigned: BenWa)

Tracking

unspecified
mozilla19
x86_64
Windows 7
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(b2g18? affected)

Details

Attachments

(3 attachments, 5 obsolete attachments)

(Reporter)

Description

5 years ago
< 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.
(Reporter)

Updated

5 years ago
Blocks: 799640
(Assignee)

Comment 1

5 years ago
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.
(Assignee)

Comment 2

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

Comment 3

5 years ago
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?
(Assignee)

Comment 5

5 years ago
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.
(Reporter)

Comment 7

5 years ago
(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
(Reporter)

Comment 8

5 years ago
(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
(Assignee)

Comment 9

5 years ago
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.
(Assignee)

Comment 10

5 years ago
Neither of these options work. I'm giving up until I can steal some of Ehsan time to help me debug this.
(Assignee)

Comment 11

5 years ago
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.
(Reporter)

Comment 12

5 years ago
(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.
(Assignee)

Comment 13

5 years ago
Created attachment 671015 [details] [diff] [review]
use stackwalk on win/mac

Not strictly needed but giving better stacks.
Assignee: nobody → bgirard
Status: NEW → ASSIGNED
Attachment #671015 - Flags: review?(ehsan)
(Assignee)

Comment 14

5 years ago
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.
(Assignee)

Comment 15

5 years ago
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.  :-)
(Reporter)

Comment 18

5 years ago
(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?
(Reporter)

Comment 19

5 years ago
(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
(Assignee)

Comment 20

5 years ago
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
(Assignee)

Comment 21

5 years ago
(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.
(Assignee)

Comment 22

5 years ago
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.
Attachment #671139 - Flags: review?(ehsan)
(Assignee)

Comment 23

5 years ago
Created attachment 671140 [details] [diff] [review]
add startup timeline markers
Attachment #671140 - Flags: review?(taras.mozilla)
(Assignee)

Comment 24

5 years ago
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.
Attachment #671139 - Attachment is obsolete: true
Attachment #671139 - Flags: review?(ehsan)
Attachment #671141 - Flags: review?(ehsan)

Updated

5 years ago
Attachment #671141 - Flags: review?(ehsan) → review+
(Assignee)

Comment 25

5 years ago
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.
(Assignee)

Comment 26

5 years ago
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.
(Reporter)

Comment 27

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

lovely hack
Attachment #671140 - Flags: review?(taras.mozilla) → review+
(Reporter)

Comment 28

5 years ago
(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
(Reporter)

Comment 29

5 years ago
(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
(Assignee)

Comment 30

5 years ago
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
(Assignee)

Updated

5 years ago
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)
(Assignee)

Comment 33

5 years ago
Created attachment 671154 [details] [diff] [review]
save markers

Argg. I used the wrong command when exporting the patch and missed a hunk :(
Attachment #671154 - Flags: review?(ehsan)

Updated

5 years ago
Attachment #671154 - Flags: review?(ehsan) → review+
(Assignee)

Comment 34

5 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/6886bd9090c3
https://hg.mozilla.org/integration/mozilla-inbound/rev/2d29c74b9c9c
Whiteboard: [leave open]
https://hg.mozilla.org/mozilla-central/rev/6886bd9090c3
https://hg.mozilla.org/mozilla-central/rev/2d29c74b9c9c
(Assignee)

Comment 36

5 years ago
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-
(Assignee)

Comment 38

4 years ago
Created attachment 681693 [details] [diff] [review]
add startup timeline markers
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+
(Assignee)

Comment 40

4 years ago
Created attachment 682058 [details] [diff] [review]
add startup timeline markers
Attachment #681693 - Attachment is obsolete: true
Attachment #682058 - Flags: review+
(Assignee)

Comment 41

4 years ago
Created attachment 682065 [details] [diff] [review]
add startup timeline markers
Attachment #682058 - Attachment is obsolete: true
Attachment #682065 - Flags: review+
(Assignee)

Comment 42

4 years ago
https://hg.mozilla.org/integration/mozilla-inbound/rev/bbd553b9d234
Whiteboard: [leave open]
https://hg.mozilla.org/mozilla-central/rev/bbd553b9d234
Status: ASSIGNED → RESOLVED
Last Resolved: 4 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?
status-b2g18: --- → affected
tracking-b2g18: --- → ?
(Assignee)

Comment 45

4 years ago
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? → ---

Updated

3 years ago
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.