add profiler markers for key browser element events

RESOLVED FIXED in 2.0 S1 (9may)

Status

defect
P1
normal
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: huseby, Assigned: huseby)

Tracking

({perf})

unspecified
2.0 S1 (9may)

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [c=devtools p=4 s= u=1.4])

Attachments

(2 attachments, 4 obsolete attachments)

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.
Assignee: nobody → dhuseby
Whiteboard: [c= p= s= u=] → [c= p=4 s= u=]
Assignee: dhuseby → nobody
Priority: -- → P3
Whiteboard: [c= p=4 s= u=] → [c=profiling p=4 s= u=]
Summary: add JS calls to start/stop profiler tracing → add JS calls to add profiler markers
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.
Blocks: 960224
No longer blocks: 960224
Whiteboard: [c=profiling p=4 s= u=] → [c=profiling p=1 s= u=]
Blocks: 960224
Blocks: 952640
Blocks: 950673
No longer blocks: 950673, 952640
Summary: add JS calls to add profiler markers → add JS call to add profiler markers
Posted patch first try (obsolete) — Splinter Review
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.
Attachment #8385633 - Flags: feedback?(bgirard)
No longer blocks: 960224
Assignee: nobody → dhuseby
Status: NEW → ASSIGNED
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?
Attachment #8385633 - Flags: feedback?(bgirard)
Priority: P3 → P1
Whiteboard: [c=profiling p=1 s= u=] → [c=profiling p=2 s= u=]
Whiteboard: [c=profiling p=2 s= u=] → [c=devtools p=2 s= u=]
Blocks: 950673
blocking-b2g: --- → 1.4+
Component: General → Performance
Whiteboard: [c=devtools p=2 s= u=] → [c=devtools p=2 s= u=1.4]
Whiteboard: [c=devtools p=2 s= u=1.4] → [c=devtools p=4 s= u=1.4]
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.
Flags: needinfo?(dhuseby)
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.
Flags: needinfo?(dhuseby)
(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.
Posted patch Bug_972075_Part1.patch (obsolete) — Splinter Review
First part of this adds markers for key events during app load.
Attachment #8385633 - Attachment is obsolete: true
(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 ?
Flags: needinfo?(dhuseby)
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.
Flags: needinfo?(dhuseby)
No longer blocks: 950673
Posted patch Bug_972075_Final.patch (obsolete) — Splinter Review
Trimming this bug down to just adding profiler markers for key browser element events.
Attachment #8410090 - Attachment is obsolete: true
Summary: add JS call to add profiler markers → add profiler markers for key browser element events
blocking-b2g: 1.4+ → ---
Attachment #8412703 - Flags: review?(bgirard)
Attachment #8412703 - Flags: review?(21)
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 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.
Attachment #8412703 - Flags: review?(bgirard) → review+
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.
Attachment #8412703 - Flags: review?(21) → feedback+
(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.
(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 ?
I'll have a new patch for review today.
Posted image markers.png
profiling markers for key window events.
Posted patch Bug_972075_Final.patch (obsolete) — Splinter Review
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.
Attachment #8412703 - Attachment is obsolete: true
Attachment #8414915 - Flags: review?(bgirard)
Attachment #8414915 - Flags: feedback?(21)
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.
Attachment #8414915 - Flags: review?(bgirard) → review-
I meant to add 'See comment 12 for details'
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 ;)
Attachment #8414915 - Flags: feedback?(21) → feedback-
alright, fixed the #define and firing the event even when the profiler isn't loaded.  thanks for the great reviews.
Attachment #8414915 - Attachment is obsolete: true
Attachment #8417721 - Flags: review?(bgirard)
Attachment #8417721 - Flags: review?(21)
Attachment #8417721 - Flags: review?(bgirard) → review+
the try looks good to me.
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/42c2a08c6f7d
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → 2.0 S1 (9may)
You need to log in before you can comment on or make changes to this bug.