Last Comment Bug 453650 - mechanism for tracking reflows in debugger
: mechanism for tracking reflows in debugger
Status: RESOLVED FIXED
[firebug-p3]
: dev-doc-needed
Product: Core
Classification: Components
Component: Layout (show other bugs)
: Trunk
: All All
: -- normal with 1 vote (vote)
: mozilla24
Assigned To: Tim Taubert [:ttaubert]
:
Mentors:
Depends on:
Blocks: 821829 876218 529086 926371
  Show dependency treegraph
 
Reported: 2008-09-04 07:49 PDT by Rob Campbell [:rc] (:robcee)
Modified: 2013-10-14 04:20 PDT (History)
30 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
implement reflow observers for docShells (15.00 KB, patch)
2013-05-26 06:20 PDT, Tim Taubert [:ttaubert]
bzbarsky: feedback+
Details | Diff | Review
implement reflow observers for docShells, v2 (16.95 KB, patch)
2013-05-30 23:57 PDT, Tim Taubert [:ttaubert]
bzbarsky: review+
Details | Diff | Review

Description Rob Campbell [:rc] (:robcee) 2008-09-04 07:49:17 PDT
To help out with webpage performance debugging, we'd like some mechanism to determine when reflows are occurring. Whether that's an event or something lower-level that we can query, this would be helpful. There are likely some other related bugs that could help out here. Q.v., bug 239074 - "onresize not firing".

This is a follow-up to a discussion with roc during the mozilla summit. Not sure if this got filed afterwards.
Comment 1 Rob Campbell [:rc] (:robcee) 2008-09-04 07:50:10 PDT
that should be "onpaint events not firing".
Comment 2 Rob Campbell [:rc] (:robcee) 2009-10-28 07:24:05 PDT
this is something we'd still like to have. We have moz_after_paint which is a step in the right direction, but would still be nice to have an event that tells us when a reflow occurs.
Comment 3 Boris Zbarsky [:bz] (Out June 25-July 6) 2009-10-28 08:59:55 PDT
What information do you want about the reflow?  Or just "a reflow occurred sometime in the past"?
Comment 4 Rob Campbell [:rc] (:robcee) 2009-10-29 09:48:14 PDT
yes, a reflow happened, ideally with a timestamp.
Comment 5 Boris Zbarsky [:bz] (Out June 25-July 6) 2009-10-29 09:58:20 PDT
What are you going to do with the information?

(Sorry for the questions, but I'm really trying to understand exactly what information you guys are trying to present....)
Comment 6 Rob Campbell [:rc] (:robcee) 2009-10-29 11:01:13 PDT
the thinking was we could place these types of events in the Net panel similar to loaded and DOMContentLoaded. That panel could become more of a generic timeline.

Alternatively, these events could be sent to a debugging console.

Another nice-to-have bit of information could be what rule caused the reflow to happen.
Comment 7 Boris Zbarsky [:bz] (Out June 25-July 6) 2009-10-29 11:13:19 PDT
Well... exactly does a list of reflows+timestamps tell you?

What do you mean by "what rule"?
Comment 8 Rob Campbell [:rc] (:robcee) 2009-10-29 11:47:24 PDT
if a particular CSS rule cause a reflow to happen.
Comment 9 Boris Zbarsky [:bz] (Out June 25-July 6) 2009-10-29 11:53:41 PDT
For what it's worth, most reflows are triggered by (more or less in order), inline style changes, content changes (nodes being inserted/removed or text in textnodes being changed), changes to node classes (which do change what rules apply, but there's no single rule which "causes" the reflow), and window resizes.

Those first two are by far the most common.
Comment 10 Rob Campbell [:rc] (:robcee) 2009-10-30 05:43:56 PDT
ok, that's good information. Not sure how feasible my request to have a reflow tagged with what caused it is based on this, but it's a nice dream. At the very least, a timestamped reflow event could be enough to piece together what happened based on other logged information.
Comment 11 Boris Zbarsky [:bz] (Out June 25-July 6) 2009-10-30 08:47:21 PDT
OK.  Want to do this?  You'd presumably want to post an event (asynchronously) in the callers of PresShell::DoReflow.

One thing that might be worth including in the event is whether the reflow was interruptible or not.  If not, that usually means the page forced out reflow via some sort of "ask for layout information" type call; minimizing those is a good idea on the part of the webpage.
Comment 12 Rob Campbell [:rc] (:robcee) 2009-10-30 11:15:28 PDT
yeah, I can take this. I'll post some follow-up questions here or in IRC if necessary. Doesn't look like that many callers, fewer if we exclude svg.
Comment 13 Steve Roussey (:sroussey) 2010-02-11 14:18:21 PST
As to why we would want them, see:

http://code.google.com/p/fbug/issues/detail?id=2760
http://fbug.googlecode.com/issues/attachment?aid=-6997391556991068354&name=apu-log.png&inline=1
http://code.google.com/webtoolkit/speedtracer/

So, for the timeline type analysis, these additions would be useful:
 - style recalc
 - script compilation / evaluation (bug #531395)
 - html parsing
 - layout/reflow (this bug)

Also, it would be good to know some of these events when single-stepping in a debugger. For example, knowing that when stepping over a line of JS that it caused a layout to occur. I think people would write faster code if they saw notifications appear in their debugger telling them that their code just causes these calculations. All of this to make the browser less of a black box.

Also, when profiling, it would be helpful to sum up these calls with the JS calls, as they are just as important to know. I'll file firebug issue for that.
Comment 14 Rob Campbell [:rc] (:robcee) 2010-02-11 14:52:39 PST
and just a follow-up. I am still planning on doing this, but have some other work to do before I can get to it. Thanks for the extra info, Steve.
Comment 15 Dave Camp (:dcamp) 2012-02-08 17:00:11 PST
We discussed this on the phone today, and what we'd like is an API that gives us a way to attach an observer to a given docshell (and its children probably?) and enable a debugging/profiling mode.  When that observer is present, we'd like:

a) Notifications of reflow begin/end times.
b) Notifications/stack traces for calls that force reflow (maybe just notification - our observer can deal with grabbing stack traces as long as it's a synchronous notification) 
c) Notifications/stack traces for calls that mark the layout tree dirty.

Any objections to using this bug for a) and filing followups for b) and c)?
Comment 16 Robert O'Callahan (:roc) (Exited; email my personal email if necessary) 2012-02-08 18:08:51 PST
You probably also want something to get notifications for changes that cause style to need to be recomputed.
Comment 17 Boris Zbarsky [:bz] (Out June 25-July 6) 2012-02-08 18:52:46 PST
Yeah, I was lumping it in with (c) but maybe we want two separate notifications....
Comment 18 Rob Campbell [:rc] (:robcee) 2012-02-08 19:17:00 PST
(In reply to Dave Camp (:dcamp) from comment #15)
> We discussed this on the phone today, and what we'd like is an API that
> gives us a way to attach an observer to a given docshell (and its children
> probably?) and enable a debugging/profiling mode.  When that observer is
> present, we'd like:
> 
> a) Notifications of reflow begin/end times.
> b) Notifications/stack traces for calls that force reflow (maybe just
> notification - our observer can deal with grabbing stack traces as long as
> it's a synchronous notification) 
> c) Notifications/stack traces for calls that mark the layout tree dirty.
> 
> Any objections to using this bug for a) and filing followups for b) and c)?

nope!
Comment 19 Jan Honza Odvarko [:Honza] 2012-02-09 06:11:02 PST
Could the notification also have a timestamp that is generated by the same timer as events sent by e.g. nsIHttpActivityDistrubutor? This would allow to see all events within the same timeline.

Honza
Comment 20 Boris Zbarsky [:bz] (Out June 25-July 6) 2012-02-09 07:57:33 PST
Sure (though the timestamp from the activity distributor is pretty broken, being wall-clock time, so having to match it makes me sad).
Comment 21 Boris Zbarsky [:bz] (Out June 25-July 6) 2012-02-09 07:58:24 PST
In any case, this bug needs an owner.  Do we have someone interested in doing it, or should I just take it?
Comment 22 Rob Campbell [:rc] (:robcee) 2012-02-10 08:11:11 PST
If you think using the activity distributor will make the timing less accurate and you have an alternative, you should use it. I'd prefer accuracy over convenience.

And yes, please feel free to take this!
Comment 23 Robert O'Callahan (:roc) (Exited; email my personal email if necessary) 2012-02-13 00:41:38 PST
(In reply to Boris Zbarsky (:bz) from comment #20)
> Sure (though the timestamp from the activity distributor is pretty broken,
> being wall-clock time, so having to match it makes me sad).

Is that the thing that gets used for the Navigation Timing API?

I actually think it's pretty important that all these timing APIs use a consistent timeline.
Comment 24 Jan Honza Odvarko [:Honza] 2012-02-13 02:29:13 PST
(In reply to Robert O'Callahan (:roc) (Mozilla Corporation) from comment #23)
> I actually think it's pretty important that all these timing APIs use a
> consistent timeline.
Yes, precisely!
Honza
Comment 25 Boris Zbarsky [:bz] (Out June 25-July 6) 2012-02-13 05:21:18 PST
Navigation timing records the value of PR_Now()/PR_USEC_TO_MSEC at navigation start, and then measures TimeDurations from that point.  Values reported to JS are milliseconds from epoch gotten by adding the TimeDuration.toMilliseconds() to the navigation start time.  Importantly, this means that the values from navigation timing are only accurate to 1ms or so.  They're integer numbers of milliseconds since the epoch, in theory.

The times from the activity distributor are pure PR_Now() times.  That means they are integer numbers of wall-clock _microseconds_ since the epoch.

Now back to our use case.  We need sub-millisecond precision, I think.  We could try to match navigation timing in the sense of returning the navigation start time plus the relevant time duration.  If we want to match the scale too, we could return a double instead of an integer, so we can measure sub-millisecond times.

I am NOT going to mess with the activity distributor in this bug.
Comment 26 Robert O'Callahan (:roc) (Exited; email my personal email if necessary) 2012-02-13 12:52:45 PST
(In reply to Boris Zbarsky (:bz) from comment #25)
> Now back to our use case.  We need sub-millisecond precision, I think.  We
> could try to match navigation timing in the sense of returning the
> navigation start time plus the relevant time duration.  If we want to match
> the scale too, we could return a double instead of an integer, so we can
> measure sub-millisecond times.

That sounds perfect.
Comment 27 Paul Rouget [:paul] 2012-06-11 03:03:48 PDT
Is this bug still on anyone's radar?
Comment 28 Boris Zbarsky [:bz] (Out June 25-July 6) 2012-06-11 19:35:54 PDT
I haven't had time to get to it.  Help very much wanted.
Comment 29 Tim Taubert [:ttaubert] 2013-05-26 06:20:13 PDT
Created attachment 754226 [details] [diff] [review]
implement reflow observers for docShells

I took a stab at this because we also need it for bug 876218.

In this patch, timestamps are doubles (DOMHighResTimeStamps) and should be as described in comment #25. Reflow observers are notified synchronously because I figured that would good for tools that need stack traces of reflows (like bug 821829).
Comment 30 Boris Zbarsky [:bz] (Out June 25-July 6) 2013-05-28 21:49:34 PDT
Do we want these observers to live across navigations, as in the attached patch, or do we want them per-document?
Comment 31 Tim Taubert [:ttaubert] 2013-05-29 00:06:26 PDT
(In reply to Boris Zbarsky (:bz) from comment #30)
> Do we want these observers to live across navigations, as in the attached
> patch, or do we want them per-document?

That's a good question. I figure it might be beneficial for devtools if they live across navigations? For my use case I don't particularly need that to be the case, though. Is there any downsides to the current approach?
Comment 32 Boris Zbarsky [:bz] (Out June 25-July 6) 2013-05-29 07:25:52 PDT
Well, it makes it very easy for an observer to stick around for a long time (which may be either good or bad depending on use cases) and it makes reflows a tad slower because you have to get the docshell...  Apart from that, probably not.

Mike, what behavior would devtools want here?
Comment 33 Michael Ratcliffe PTO -> Fri, 24 Jun 2016 [:miker] [:mratcliffe] 2013-05-29 08:23:39 PDT
The developer toolbox sticks around for the life of the tab so it is better for us if the observer can do the same.
Comment 34 Boris Zbarsky [:bz] (Out June 25-July 6) 2013-05-30 10:49:18 PDT
Comment on attachment 754226 [details] [diff] [review]
implement reflow observers for docShells

OK, so I guess this is reasonable.  Three things that I'm worried about here:

1)  This call is happening under a scriptblocker and while the presshell is in an inconsistent state.  If you try to mutate a DOM from that notification, bad things will happen.  I would prefer it if we recorded the pending notifications on the presshell and reported them all in DidDoReflow, right before possibly firing the synth mouse move stuff.

2)  The fact that adding a reflow observer twice and removing it once causes it to not be registered is a bit odd.  Is that what we really want?

3)  window->GetPerformance() can be null in some cases, I think.  We should handle that.
Comment 35 Boris Zbarsky [:bz] (Out June 25-July 6) 2013-05-30 10:50:20 PDT
Oh, and thank you for doing this!
Comment 36 Tim Taubert [:ttaubert] 2013-05-30 23:57:58 PDT
Created attachment 756412 [details] [diff] [review]
implement reflow observers for docShells, v2

(In reply to Boris Zbarsky (:bz) from comment #34)
> 1)  This call is happening under a scriptblocker and while the presshell is
> in an inconsistent state.  If you try to mutate a DOM from that
> notification, bad things will happen.  I would prefer it if we recorded the
> pending notifications on the presshell and reported them all in DidDoReflow,
> right before possibly firing the synth mouse move stuff.

Ok, so what I did is record the start time in WillDoReflow() and notify observers in DidRoReflow(). Do you think it is sufficient to notify about a block of reflow commands that has been processed? I'm not sure we really need notifications for every single reflow in that batch.

> 2)  The fact that adding a reflow observer twice and removing it once causes
> it to not be registered is a bit odd.  Is that what we really want?

True, that's a little odd. I modified the patch so that we now fail when trying to add an observer a second time and also fail when trying to remove unregistered observers.

> 3)  window->GetPerformance() can be null in some cases, I think.  We should
> handle that.

Done.
Comment 37 Boris Zbarsky [:bz] (Out June 25-July 6) 2013-05-31 12:16:27 PDT
Comment on attachment 756412 [details] [diff] [review]
implement reflow observers for docShells, v2

>+PresShell::GetPerformanceNow() {

Put the '{' on the next line, please.

This looks great.  r=me
Comment 38 Tim Taubert [:ttaubert] 2013-06-01 03:06:43 PDT
https://hg.mozilla.org/integration/fx-team/rev/e5bda8cacbda
Comment 39 Tim Taubert [:ttaubert] 2013-06-01 04:08:43 PDT
Yeah, that didn't go well.

https://hg.mozilla.org/integration/fx-team/rev/d1ac2fce4847
Comment 40 Tim Taubert [:ttaubert] 2013-06-01 04:09:05 PDT
(That should've said I backed it out again.)
Comment 41 Tim Taubert [:ttaubert] 2013-06-01 05:28:41 PDT
Yeah, that should be

> mDocument->GetInnerWindow()->GetPerformance()->Now()

because nsPIDOMWindow::GetPerformance() does

> MOZ_ASSERT(IsInnerWindow());
Comment 42 Tim Taubert [:ttaubert] 2013-06-01 09:25:09 PDT
Relanded using GetInnerWindow():

https://hg.mozilla.org/integration/fx-team/rev/18fc62fd8dcc

Try was green before:

https://tbpl.mozilla.org/?tree=Try&rev=989771ae6f40
Comment 43 Tim Taubert [:ttaubert] 2013-06-01 11:57:45 PDT
https://hg.mozilla.org/mozilla-central/rev/18fc62fd8dcc
Comment 44 Jan Honza Odvarko [:Honza] 2013-06-03 05:40:00 PDT
I tried to register an observer for the reflow events and I am seeing an exception:

reflowObserver.initContext;  Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIDocShell.addWeakReflowObserver]

My observer looks like as follows:

var observer =
{
    reflow: function(start, end)
    {
    },

    reflowInterruptible: function(start, end)
    {
    },
}

browser.docShell.addWeakReflowObserver(observer);

What am I doing wrong?
Or is there a doc I could follow?

Honza
Comment 45 Tim Taubert [:ttaubert] 2013-06-03 05:44:51 PDT
Hey Honza, you can take a look at the test:

https://hg.mozilla.org/mozilla-central/file/18fc62fd8dcc/docshell/test/chrome/test_bug453650.xul

Basically, your observer is missing the right interfaces:

> var observer = {
>   reflow: function (start, end) {
>   },
>   
>   reflowInterruptible: function (start, end) {
>   },
>   
>   QueryInterface: function (iid) {
>     if (Ci.nsIReflowObserver.equals(iid) ||
>         Ci.nsISupportsWeakReference.equals(iid) ||
>         Ci.nsISupports.equals(iid))
>       return this;
>     throw Cr.NS_ERROR_NO_INTERFACE;
>   }
> };
Comment 46 Jan Honza Odvarko [:Honza] 2013-06-03 05:48:05 PDT
(In reply to Tim Taubert [:ttaubert] from comment #45)
> Hey Honza, you can take a look at the test:
> 
> https://hg.mozilla.org/mozilla-central/file/18fc62fd8dcc/docshell/test/
> chrome/test_bug453650.xul
> 
> Basically, your observer is missing the right interfaces:
Works now, thanks Tim!
Honza

Note You need to log in before you can comment on or make changes to this bug.