Closed Bug 453650 Opened 16 years ago Closed 11 years ago

mechanism for tracking reflows in debugger

Categories

(Core :: Layout, defect)

Product:
Core
Component:
Layout
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla24

People

(Reporter: rcampbell, Assigned: ttaubert)

References

(Blocks 2 open bugs)

Details

(Keywords: dev-doc-needed, Whiteboard: [firebug-p3])

Attachments

(1 file, 1 obsolete file)

implement reflow observers for docShells, v2
16.95 KB, patch
bzbarsky
: review+
Details | Diff | Splinter Review 
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.
Whiteboard: [firebug-p3]
that should be "onpaint events not firing".
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.
What information do you want about the reflow?  Or just "a reflow occurred sometime in the past"?
yes, a reflow happened, ideally with a timestamp.
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....)
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.
Well... exactly does a list of reflows+timestamps tell you?

What do you mean by "what rule"?
if a particular CSS rule cause a reflow to happen.
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.
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.
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.
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.
Blocks: 529086
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.
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.
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)?
You probably also want something to get notifications for changes that cause style to need to be recomputed.
Yeah, I was lumping it in with (c) but maybe we want two separate notifications....
(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!
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
Sure (though the timestamp from the activity distributor is pretty broken, being wall-clock time, so having to match it makes me sad).
In any case, this bug needs an owner.  Do we have someone interested in doing it, or should I just take it?
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!
(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.
(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
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.
(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.
Is this bug still on anyone's radar?
I haven't had time to get to it.  Help very much wanted.
Blocks: 821829
Blocks: 876218
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).
Attachment #754226 - Flags: feedback?(bzbarsky)
Do we want these observers to live across navigations, as in the attached patch, or do we want them per-document?
Flags: needinfo?(ttaubert)
(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?
Flags: needinfo?(ttaubert)
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?
Flags: needinfo?(mratcliffe)
The developer toolbox sticks around for the life of the tab so it is better for us if the observer can do the same.
Flags: needinfo?(mratcliffe)
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.
Attachment #754226 - Flags: feedback?(bzbarsky) → feedback+
Oh, and thank you for doing this!
(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.
Attachment #754226 - Attachment is obsolete: true
Attachment #756412 - Flags: review?(bzbarsky)
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
Attachment #756412 - Flags: review?(bzbarsky) → review+
https://hg.mozilla.org/integration/fx-team/rev/e5bda8cacbda
Assignee: nobody → ttaubert
Status: NEW → ASSIGNED
Keywords: dev-doc-needed
(That should've said I backed it out again.)
Yeah, that should be

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

because nsPIDOMWindow::GetPerformance() does

> MOZ_ASSERT(IsInnerWindow());
https://hg.mozilla.org/mozilla-central/rev/18fc62fd8dcc
Status: ASSIGNED → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla24
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
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;
>   }
> };
(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
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: