972075 - add profiler markers for key browser element events

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Performance, defect, P1)

Description

[Dave Huseby [:huseby]]

I think it is time we exposed functions in the DOM for adding start/stop tracing markers into the profile output.  The goal is to allow the perf team to better debug JS related performance issues by enabling us to visualize the execution time (in wall clock) of JS functions as well the order in which they execute.

This would be most helpful when debugging FxOS application startup performance issues.  I want to be able to start the tracer when the app launches and stop the tracer when the mozbrowserloadend event fires.

It would also be really helpful to be able to visualize beginning and end of any idle JS functions so that we can see when they execute and how long the take, relative to other things in the timeline.  There's also an opportunity for utilizing this for marking up networking code, IO code, etc.

Currently, the only code that uses the profiler tracing functionality is the Compositor, which does so from C++.  It uses tracing to visualize the layout, rasterizing, and compositing of the rendering thread.  BenWa pointed me to the function it uses: profiler_tracing (http://mzl.la/MLZumM).

My proposal is to extend the nsIProfiler interface (http://mzl.la/MM49oz) to include methods called TracingStart and TracingEnd that take a category and name.  Those calls will results in calls to profiler_tracing (http://mzl.la/MM4UxS) which will add the markers to the sampling profiler output.

To expose this functionality to all apps, I propose extending the console object with TracingStart and TracingEnd methods that call the profiler's methods of the same name.

The last part of the proposal is to modify cleopatra so that it will render a timeline for each category with boxes for each start/stop markers of the same name.

Comment 1

[Dave Huseby [:huseby]]

A simpler solution is to just use the existing ability to add markers to the profiler timeline.  The only thing left to do is add it to the Console object API, have that send events to the profile actor that then causes the profiler to add a marker.

Comment 2

[Dave Huseby [:huseby]]

Attachment: first try

I think I've got everything glued up properly but for some reason I'm not seeing the markers in the profiler .sym/.txt files output by ./profile.sh capture.

Comment 3

[Benoit Girard (:BenWa)]

Comment on attachment 8385633 [details] [diff] [review]
first try

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

I'm not the right person to review this. I glanced at the code and couldn't follow the profile.js but perhaps it's just because I don't know that code.

::: toolkit/devtools/server/actors/profiler.js
@@ +94,5 @@
>      return { "msg": "profiler stopped" }
>    },
> +  onAddProfileMarker: function(aRequest) {
> +    if (!this._started) {
> +      return { "msg": "profiler not running" }

I'm not sure why this would have a special profiler not running message when others don't need it? Maybe that's ok

@@ +233,5 @@
> +        return void send({
> +          name: name,
> +          currentTime: 0,
> +          action: "profileMarker"
> +        });

I don't understand? If the profiler isn't running we shouldn't send this? Why is currentTime 0?

@@ +242,5 @@
> +      });
> +
> +      return void send({
> +        name: name,
> +        currentTime: resp.currentTime,

Why is currentTime the response from onIsActive?

Comment 4

[Kai-Chih Hu [:khu]]

This bug sounds like a very good idea! Thank you! 

By the way, I've some questions: 
1. Do we have any update? We don't have any updates at least 2 weeks. 
2. I know this bug will bring us lots of benefits. May I know if there has any reason that we should mark this bug as a blocker(1.4+)? 

Thank you.

Comment 5

[Dave Huseby [:huseby]]

I have 99% of the code done.  I'm just trying to figure out why the markers aren't actually in the data output by the profiler.  I'm pretty sure it has to do with the markers being recorded from one of the threads not being profiled and therefor not in the output.  I haven't had the time to figure it out completely yet.

This is blocking 1.4 because there are several outstanding 1.4 blocker bugs that could use this to figure out how to fix some regressions in app launch times.  Specifically Bug 950673.

Comment 6

[Kai-Chih Hu [:khu]]

(In reply to Dave Huseby [:huseby] from comment #5)
> I have 99% of the code done.  I'm just trying to figure out why the markers
> aren't actually in the data output by the profiler.  I'm pretty sure it has
> to do with the markers being recorded from one of the threads not being
> profiled and therefor not in the output.  I haven't had the time to figure
> it out completely yet.

Thanks, Dave! By the way, if you need help, please let us know. 
The end of 1.4 is coming, and just curious if there has anything we can help. :-)

> 
> This is blocking 1.4 because there are several outstanding 1.4 blocker bugs
> that could use this to figure out how to fix some regressions in app launch
> times.  Specifically Bug 950673.

Comment 7

[Dave Huseby [:huseby]]

Attachment: Bug_972075_Part1.patch

First part of this adds markers for key events during app load.

Comment 8

[bhavana bajaj [:bajaj]]

(In reply to Dave Huseby [:huseby] from comment #5)
> I have 99% of the code done.  I'm just trying to figure out why the markers
> aren't actually in the data output by the profiler.  I'm pretty sure it has
> to do with the markers being recorded from one of the threads not being
> profiled and therefor not in the output.  I haven't had the time to figure
> it out completely yet.
> 
> This is blocking 1.4 because there are several outstanding 1.4 blocker bugs
> that could use this to figure out how to fix some regressions in app launch
> times.  Specifically Bug 950673.

Hey dave, it seems like Bug 950673 has an independent patch that could fix the issue. In that case, is this still needed ?

Comment 9

[Dave Huseby [:huseby]]

Yes, if Bug 950673 is fixed, go ahead an land it.  It's not really blocked by this.  I was thinking that having it would let us get a deeper understanding of the perf issues that were causing Bug 950673.

I fix the dependency.

Comment 10

[Dave Huseby [:huseby]]

Attachment: Bug_972075_Final.patch

Trimming this bug down to just adding profiler markers for key browser element events.

Comment 11

[Dave Huseby [:huseby]]

It turns out there is deeper engineering work necessary to expose console.addMarker() to app JS.  I have decided to cut this bug down in scope to just adding profiler markers for key browser element events when MOZ_PROFLING is defined during the build.

Comment 12

[Benoit Girard (:BenWa)]

Comment on attachment 8412703 [details] [diff] [review]
Bug_972075_Final.patch

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

r+ with s/MOZ_PROFILING/MOZ_ENABLE_PROFILER_SPS

::: toolkit/modules/Services.jsm
@@ +63,5 @@
>    ["logins", "@mozilla.org/login-manager;1", "nsILoginManager"],
>    ["obs", "@mozilla.org/observer-service;1", "nsIObserverService"],
>    ["perms", "@mozilla.org/permissionmanager;1", "nsIPermissionManager"],
>    ["prompt", "@mozilla.org/embedcomp/prompt-service;1", "nsIPromptService"],
> +#ifdef MOZ_PROFILING

This is misusing MOZ_PROFILING:
http://mxr.mozilla.org/mozilla-central/source/configure.in#1604

- It's mean to detect if we're building the binary with unwind information.
- Markers don't rely on unwind information.
- enable-profiling should not change the runtime behavior. That is enable-profiling shouldn't be profiling something different then what we ship.

You should instead MOZ_ENABLE_PROFILER_SPS. Note that this code is enabled on builds we ship but if we're not profiling then markers will do nothing but check if we're profiling.

Comment 13

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 8412703 [details] [diff] [review]
Bug_972075_Final.patch

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

I would like to see a new version before r+'ing. But it sounds good to me in general.

::: dom/browser-element/BrowserElementParent.jsm
@@ +33,5 @@
>  
> +function profileMarker(name) {
> +  if (Services.profiler !== undefined) {
> +    Services.profiler.AddMarker(name);
> +  }

if ('profiler' in Services) {
  Services.profiler.AddMarker(name);
}

@@ +34,5 @@
> +function profileMarker(name) {
> +  if (Services.profiler !== undefined) {
> +    Services.profiler.AddMarker(name);
> +  }
> +}

Btw do you really need this method or can you just move the check into fireProfileEventFromMsg ?

@@ +265,1 @@
>        "titlechange": this._fireEventFromMsg,

I wonder if we also want 'titlechange'. I have seen a few cases where we handle titlechange in the system app and spend some cpu cycles on it. With the new interfaces for Haida my understanding is that titlechange will be even more important and can cause some reflows. So maybe we want to see that as well.

All this assume that the reasons why you want to mark |close| and |resize| is to be able to instantly see them in the profiler ?

That said I'm not strong on this, so if you feel like this is not useful, that's OK.

Comment 14

[[:fabrice] Fabrice Desré]

(In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails, needinfo? please) from comment #13)
> Comment on attachment 8412703 [details] [diff] [review]
> Bug_972075_Final.patch
> 
> Review of attachment 8412703 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I would like to see a new version before r+'ing. But it sounds good to me in
> general.
> 
> ::: dom/browser-element/BrowserElementParent.jsm
> @@ +33,5 @@
> >  
> > +function profileMarker(name) {
> > +  if (Services.profiler !== undefined) {
> > +    Services.profiler.AddMarker(name);
> > +  }
> 
> if ('profiler' in Services) {
>   Services.profiler.AddMarker(name);
> }

Services.profiler !== undefined will be faster so I would keep it that way.

Comment 15

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

(In reply to Fabrice Desré [:fabrice] from comment #14)
> (In reply to Vivien Nicolas (:vingtetun) (:21) (NOT reading bugmails,
> needinfo? please) from comment #13)
> > Comment on attachment 8412703 [details] [diff] [review]
> > Bug_972075_Final.patch
> > 
> > Review of attachment 8412703 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > I would like to see a new version before r+'ing. But it sounds good to me in
> > general.
> > 
> > ::: dom/browser-element/BrowserElementParent.jsm
> > @@ +33,5 @@
> > >  
> > > +function profileMarker(name) {
> > > +  if (Services.profiler !== undefined) {
> > > +    Services.profiler.AddMarker(name);
> > > +  }
> > 
> > if ('profiler' in Services) {
> >   Services.profiler.AddMarker(name);
> > }
> 
> Services.profiler !== undefined will be faster so I would keep it that way.

Really ?

Comment 16

[Dave Huseby [:huseby]]

I'll have a new patch for review today.

Comment 17

[Dave Huseby [:huseby]]

Attachment: markers.png

profiling markers for key window events.

Comment 18

[Dave Huseby [:huseby]]

Attachment: Bug_972075_Final.patch

I cleaned up the patch a bit.  Combined _fireProfiledEventFromMsg and profileMarker.  I kept Services.provider !== undefined.  I removed the profile markers for close and resize events.

Comment 19

[Benoit Girard (:BenWa)]

Comment on attachment 8414915 [details] [diff] [review]
Bug_972075_Final.patch

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

r- for incorrectly using MOZ_PROFILING. Removes the lines. Adding a marker while you're not actively profiling will just be a TLS lookup.

Comment 20

[Benoit Girard (:BenWa)]

I meant to add 'See comment 12 for details'

Comment 21

[Vivien Nicolas (:vingtetun) (:21) - (NOT reading bugmails, needinfo? please)]

Comment on attachment 8414915 [details] [diff] [review]
Bug_972075_Final.patch

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

::: dom/browser-element/BrowserElementParent.jsm
@@ +413,5 @@
> +  _fireProfiledEventFromMsg: function(data) {
> +    if (Services.profiler !== undefined) {
> +      Services.profiler.AddMarker(data.json.msg_name);
> +      this._fireEventFromMsg(data);
> +    }

You probably still want to fire the events even if Services.profiler is not set ;)

Comment 22

[Dave Huseby [:huseby]]

Attachment: Bug_972075_Final.patch

alright, fixed the #define and firing the event even when the profiler isn't loaded.  thanks for the great reviews.

Comment 23

[Dave Huseby [:huseby]]

try: https://tbpl.mozilla.org/?tree=Try&rev=0942b5f47600

Comment 24

[Dave Huseby [:huseby]]

the try looks good to me.

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/42c2a08c6f7d

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/42c2a08c6f7d