1104213 - capture stack traces on timeline markers

Status: VERIFIED FIXED

(DevTools :: Performance Tools (Profiler/Timeline), defect)

Description

[Tom Tromey :tromey]

As bug 1069661 noted, it would be handy if timeline markers sometimes
carried a javascript stack trace.

Comment 1

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

Here's an initial patch that adds stack traces to ConsoleTime markers.
It has a debugging hack to display the stack trace (this area needs
much more work).

Comment 2

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This version rearranges the code a bit to share some of the stack
frame management code with memory.js, and then adds a new timeline
event to transmit the frame data.

It still needs some love when displaying the frames.  They should at
least be clickable; and right now the formatting is both ugly and not
in keeping with how locations are displayed elsewhere.

Comment 3

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This version displays the stack more nicely.

Comment 4

[Tom Tromey :tromey]

Comment on attachment 8531788 [details] [diff] [review]
add stack traces to timeline markers

Olli said recently that using the cycle collector here was wrong.
So, I'm obsoleting this patch and investigating a more correct approach.

Comment 5

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This version removes the cycle collection code in favor of
PersistentRooted.

Comment 6

[Tom Tromey :tromey]

One thing I realized is that for console markers, we may want to
see the stack at the start and at the end, which this approach
doesn't really allow.  I'm not sure what to do about this yet.

Comment 7

[Tom Tromey :tromey]

(In reply to Tom Tromey :tromey from comment #6)
> One thing I realized is that for console markers, we may want to
> see the stack at the start and at the end, which this approach
> doesn't really allow.  I'm not sure what to do about this yet.

Well, duh.  I added an "endStack" member to the marker.

Comment 8

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This version includes a test case and both starting and ending stacks
for console markers.

A few notes on this patch:

I moved the stack frame cache into its own class so it could be shared
by the memory actor and the timeline.  I didn't understand why the
current code chose to store the allocation counts separately from the
frame objects, but also didn't change this.  Note that this code in
the memory actor also seems to be unused at present; but if we wanted
the memory actor to send frames to the client, we'd have to modify
_pullTimelineData to get the memory actor to register its frames with
the frame cache.

I added a new "frames" event that transfers new frame objects to the
client.  I did not go the full length of making markers into actors as
it isn't clear this is needed yet.

Maybe not quite ready for review - sending it through try to see how
it fares.

Comment 9

[Tom Tromey :tromey]

https://tbpl.mozilla.org/?tree=Try&rev=df356e5b6e57

Comment 10

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This updates the patch to try to avoid races in the new test case.

Comment 11

[Tom Tromey :tromey]

https://tbpl.mozilla.org/?tree=Try&rev=d469ad65a61e

Comment 12

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

These tests don't work for e10s, so I disabled them.
(I'm looking at making all the timeline marker tests work there
though.)

New try build:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0b5f306a3fe5

Comment 13

[Olli Pettay [:smaug][[e-mail]](vacation until July 14)]

Could you upload the generated code for ProfileTimelineMarker.webidl
(should be in <objdir>/dom/bindings/...cpp and <objdir>/dist/include/mozilla/dom/....h)

Comment 14

[Tom Tromey :tromey]

Attachment: ProfileTimelineMarkerBinding.h

Comment 15

[Tom Tromey :tromey]

Attachment: ProfileTimelineMarkerBinding.cpp

Comment 16

[Olli Pettay [:smaug][[e-mail]](vacation until July 14)]

Comment on attachment 8537445 [details] [diff] [review]
add stack traces to timeline markers

>               if (isPaint) {
>-                marker.mRectangles.Construct(layerRectangles);
>+                marker->mRectangles.Construct(layerRectangles);
>               } else {
>-                startPayload->AddDetails(marker);
>+                startPayload->AddDetails(*marker);
>               }
>-              profileTimelineMarkers.AppendElement(marker);
>+              endPayload->AddDetails(*marker);
I don't understand why we add details to startPayload conditionally, but to endPlayload always

>         // Add details specific to this marker type to aMarker.  The
>-        // standard elements have already been set.
>+        // standard elements have already been set.  This method is
>+        // called on both the starting and ending markers of a pair.
>+        // Ordinarily the ending marker doesn't need to do anything
>+        // here.
So this comment isn't quite right, since the method isn't always called on starting marker


Need some clarifications to those two.

Comment 17

[Tom Tromey :tromey]

(In reply to Olli Pettay [:smaug] from comment #16)
> Comment on attachment 8537445 [details] [diff] [review]
> add stack traces to timeline markers
> 
> >               if (isPaint) {
> >-                marker.mRectangles.Construct(layerRectangles);
> >+                marker->mRectangles.Construct(layerRectangles);
> >               } else {
> >-                startPayload->AddDetails(marker);
> >+                startPayload->AddDetails(*marker);
> >               }
> >-              profileTimelineMarkers.AppendElement(marker);
> >+              endPayload->AddDetails(*marker);
> I don't understand why we add details to startPayload conditionally, but to
> endPlayload always

There's no particularly good reason.  It's just how the code was previously.
I'll change it.

Comment 18

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

This fixes the review comment.  On irc smaug noted that what he meant
was why the "end" addition wasn't conditional; but I had read the
comment the other way.  FWIW I think making them both unconditional is
cleaner.

This version has also been rebased; and fixes a couple minor things in
marker-details.js that were pointed out by jshint.

Comment 19

[Andrei Vaida [:avaida]]

Tom, is manual QA coverage needed for this fix? If so, could you please provide a few details on how to verify it?

Comment 20

[Tom Tromey :tromey]

(In reply to Andrei Vaida, QA [:avaida] from comment #19)
> Tom, is manual QA coverage needed for this fix? If so, could you please
> provide a few details on how to verify it?

This patch isn't in yet - it still needs a review for the timeline
UI changes.

That said I am not sure whether it would need manual coverage or not.
Does the timeline feature generally need manual coverage?  If so I suppose
this would as well.

Comment 21

[Andrei Vaida [:avaida]]

(In reply to Tom Tromey :tromey from comment #20)
> (In reply to Andrei Vaida, QA [:avaida] from comment #19)
> > Tom, is manual QA coverage needed for this fix? If so, could you please
> > provide a few details on how to verify it?
> 
> This patch isn't in yet - it still needs a review for the timeline
> UI changes.
> 
> That said I am not sure whether it would need manual coverage or not.
> Does the timeline feature generally need manual coverage?  If so I suppose
> this would as well.

Generally speaking, this feature does need manual coverage. Sorry for the noise, but what I'm trying to do here is filter out exactly which fixes need verification and which don't, so I can prioritize my work better. The sooner, the better.

Thanks for your feedback, Tom. I'm gonna go ahead and set qe-verify+ for this fix, although I'm not sure exactly how to verify it manually.

Comment 22

[Tom Tromey :tromey]

(In reply to Andrei Vaida, QA [:avaida] from comment #21)

> Generally speaking, this feature does need manual coverage. Sorry for the
> noise, but what I'm trying to do here is filter out exactly which fixes need
> verification and which don't, so I can prioritize my work better. The
> sooner, the better.
> 
> Thanks for your feedback, Tom. I'm gonna go ahead and set qe-verify+ for
> this fix, although I'm not sure exactly how to verify it manually.

Thanks for explaining the situation to me.  It wasn't noise to me :-)

A simple way to test this feature would be to visit a web page that
uses console.time and console.timeEnd.  Then open the timeline and
start recording, and arrange for the console calls to happen.  Then stop
recording.

A console marker should appear on the timeline, and by clicking on it
you should see a stack trace in the marker details panel.

Comment 23

[Victor Porof [:vporof][:vp]]

Comment on attachment 8539329 [details] [diff] [review]
add stack traces to timeline markers

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

::: browser/devtools/timeline/timeline.js
@@ +337,5 @@
>     */
>    _onMarkerSelected: function(event, marker) {
>      if (event == "selected") {
> +      this.markerDetails.render(gToolbox, marker,
> +                                TimelineController.getFrames());

Looks like this could start using an options object.

this.markerDetails.render({ 
  toolbox: ...
  marker: ...
  frames: ...
}

Make sure the new performance tool won't break when changing this.

::: browser/devtools/timeline/widgets/marker-details.js
@@ +167,5 @@
> +   *        The source URL to show.
> +   * @param integer aSourceURL
> +   *        The line number to show.
> +   */
> +  viewSourceInDebugger: function(toolbox, aSourceURL, aSourceLine) {

Place this function outside the MarkerDetails object, since it's not directly related to it. And it'd be great if you used the new taskified version of this, see http://dxr.mozilla.org/mozilla-central/source/browser/devtools/performance/views/details-call-tree.js#120

@@ +214,5 @@
> +    parent.appendChild(labelName);
> +
> +    while (frameIndex > 0) {
> +      let frame = frames[frameIndex];
> +      let url = frame.source;

Nit: Just like with `url`, I'd like to see a let displayName = frame.functionDisplayName here, to make it more clear that these two properties (url and funcitonDisplayName) are going to be used to render a frame.

@@ +233,5 @@
> +        aNode.draggable = false;
> +        aNode.setAttribute("title", url);
> +
> +        let text = (WebConsoleUtils.abbreviateSourceURL(url) +
> +                        ":" + frame.line);

Nit: keep this on a single line.

::: toolkit/devtools/server/actors/timeline.js
@@ +187,5 @@
> +    }
> +
> +    let frames = this._stackFrames.makeEvent();
> +    if (frames) {
> +      events.emit(this, "frames", frames);

Emit the endTime here as well, to be consistent with the other events. Who knows when we might need it, and dealing with backwards compatibility is hard.

Comment 24

[Tom Tromey :tromey]

https://tbpl.mozilla.org/?tree=Try&rev=1ccbc0039231

Comment 25

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

Here's a new version.

I think it addresses all the review comments:

* Changed render to take an options object.

* Adapted the new performance tool.

* Moved viewSourceInDebugger outside of the MarkerDetails object.
  I just copied and pasted here; I looked at unifying the various
  copies of this function, but I think there are enough of them that
  it is better to do this as a follow-up patch.

* Introduced "let" for "url" in renderStackTrace.  Did the same for
  "line" while I was there.

* Fixed nit.

* Added endTime to frames event.

Also I updated the test to work with e10s, following how the other
tests were converted.

Comment 26

[Tom Tromey :tromey]

Comment on attachment 8542189 [details] [diff] [review]
add stack traces to timeline markers

I plan to carry over smaug's r+.

Comment 27

[Victor Porof [:vporof][:vp]]

Comment on attachment 8542189 [details] [diff] [review]
add stack traces to timeline markers

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

Very nice.

::: browser/devtools/timeline/widgets/marker-details.js
@@ +152,5 @@
> +      this.renderStackTrace(toolbox, this._parent, property, marker.stack, frames);
> +    }
> +
> +    if (marker.endStack) {
> +      this.renderStackTrace(toolbox, this._parent, "timeline.markerDetail.endStack", marker.endStack, frames);

Nit: Seeing this, it might be a good idea to make renderStackTrace also take an arguments object.

::: toolkit/devtools/server/actors/timeline.js
@@ +177,5 @@
>      for (let docShell of this.docShells) {
>        markers = [...markers, ...docShell.popProfileTimelineMarkers()];
>      }
>  
> +    for (let marker of markers) {

Nit: could you add a comment here describing what's going on? Why do we Cu.waiveXrays for example?

::: toolkit/devtools/server/actors/utils/stack.js
@@ +42,5 @@
> +   * Forget all stored frames and reset to the initialized state.
> +   */
> +  clearFrames: function() {
> +    this._framesToCounts.clear();
> +    this._framesToCounts = null;

Doing both `.clear()` and `= null` might be a bit paranoid, but ok.

Comment 28

[Tom Tromey :tromey]

Attachment: add stack traces to timeline markers

Here's a new revision that addresses the last review comments.

One quick note about those:

>> Doing both `.clear()` and `= null` might be a bit paranoid, but ok.

In this case the code was pre-existing.  Usually when I move things
around I try to modify them as little as possible to make it easier to
reason about the change.

I'm happy to change this in a separate patch if you want, just let me
know.

Comment 29

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/integration/fx-team/rev/0253e47deae7

Comment 30

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0253e47deae7

Comment 31

[Boris Zbarsky [:bzbarsky]]

Just as a note, I don't think the "stack trace can't actually cause a cycle" comment can possibly be true.  The fact that it's a temporary reference is the part that really makes things OK, no?  It would be good to get that comment updated, or the reason a cycle can't happen (if that's actually the case) very clearly documented.

Comment 32

[Tom Tromey :tromey]

(In reply to Boris Zbarsky [:bz] from comment #31)
> Just as a note, I don't think the "stack trace can't actually cause a cycle"
> comment can possibly be true.  The fact that it's a temporary reference is
> the part that really makes things OK, no?  It would be good to get that
> comment updated, or the reason a cycle can't happen (if that's actually the
> case) very clearly documented.

Yeah, maybe I see now.  Since SavedFrames are memoized, it's possible
to add properties to one from js code that would cause a cycle.  Is that
what you meant?

I will fix this comment.  CCing you on the new bug.

Comment 33

[Boris Zbarsky [:bzbarsky]]

> Since SavedFrames are memoized, it's possible
> to add properties to one from js code that would cause a cycle.  Is that
> what you meant?

What I meant is that a SavedFrame keeps its global (the window in this case, no?) alive, and people can add references to all sorts of stuff there.

Comment 34

[Tom Tromey :tromey]

(In reply to Boris Zbarsky [:bz] from comment #33)
> > Since SavedFrames are memoized, it's possible
> > to add properties to one from js code that would cause a cycle.  Is that
> > what you meant?
> 
> What I meant is that a SavedFrame keeps its global (the window in this case,
> no?) alive, and people can add references to all sorts of stuff there.

Thanks for the explanation.

Comment 35

[Andrei Vaida [:avaida]]

Verified fixed on Beta 37.0b6 (20150316202753), Aurora 38.0a2 (2015-03-16) and Nightly 39.0a1 (2015-03-16), using Ubuntu 14.04 (x64), Windows 7 (x64) and Mac OS X 10.9.5.

Comment 36

[David Lawrence [:dkl]]

Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl