926371 - Add a simple tool to display reflows

Status: VERIFIED FIXED

(DevTools :: General, defect)

Description

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

Attachment: Show reflows for b2g app WIP

It would be useful for developers to have a way to display the reflows happening on a page. For Gaia it would be useful to save some load time and to fix some responsiveness issues.

I made a small hack on top of a platform feature (bug 453650) that display the reflows (with a stack if they comes from JS) and the time spent on them. It already shows me that the LazyLoad of some of our CSS files is extremelly expensive and hurt the page responsiveness after a page load.

It also shows some weird things in the sms app.

So it would be very helpful to have that as a tool instead as a hack for app developers.

Comment 1

[Paul Rouget [:paul]]

Working on that…

Comment 2

[Paul Rouget [:paul]]

Attachment: Patch v0.1 - WIP

The plan is to create a "LOG" section in the WebConsole, that is off by default, which will show the reflow events.

Comment 3

[Panos Astithas (he/him) [:past] (please ni?)]

I wonder if we could use that new section to add other interesting events, like GC events for example. Although Log sounds too similar to the existing Logging category to be honest.

Comment 4

[Paul Rouget [:paul]]

Attachment: Patch v0.2 - WIP

Mihai, can you look at this patch? I know it's ugly, but before going further, I'll like to get your feedback.

I show the reflow in "Log" section in the CSS tab. It's disabled by default. These events are batched, so we don't get flooded with logs.

Also, how can we start recording reflow events only when the log section is activated?

Comment 5

[Paul Rouget [:paul]]

Attachment: Patch v0.3

+ function name.

Comment 6

[Paul Rouget [:paul]]

Attachment: screenshot: reflow in the homescreen app

Comment 7

[Paul Rouget [:paul]]

Comment on attachment 816623 [details] [diff] [review]
Patch v0.3

Vivien, does that address your needs? I don't show the full stack, but it opens the debugger. From here, you can add a breakpoint and start debugging. I don't show if the reflow is interruptible or not.

Comment 8

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

(In reply to Paul Rouget [:paul] from comment #7)
> Comment on attachment 816623 [details] [diff] [review]
> Patch v0.3
> 
> Vivien, does that address your needs? I don't show the full stack, but it
> opens the debugger. From here, you can add a breakpoint and start debugging.
> I don't show if the reflow is interruptible or not.

I think that's good enough as a start yes. Then we can iterate from that.

Comment 9

[Mihai Sucan [:msucan]]

Comment on attachment 816623 [details] [diff] [review]
Patch v0.3

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

Patch looks good. See comments below for improvements.

::: browser/devtools/webconsole/webconsole.js
@@ +1541,5 @@
> +    let span = this.document.createElementNS(XHTML_NS, "span");
> +    if (functionName) {
> +      span.textContent = "reflow (" + functionName + "): " + duration + "ms";
> +    } else {
> +      span.textContent = "reflow: " + duration + "ms";

span.textContent needs to be a localizable string.

@@ +1543,5 @@
> +      span.textContent = "reflow (" + functionName + "): " + duration + "ms";
> +    } else {
> +      span.textContent = "reflow: " + duration + "ms";
> +    }
> +    span.draggable = false;

draggable=false is needed only for anchors.

@@ +2313,5 @@
>     *         output node.
>     */
>    createMessageNode:
>    function WCF_createMessageNode(aCategory, aSeverity, aBody, aSourceURL,
> +                                 aSourceLine, aClipboardText, aLevel, aTimeStamp, aTarget)

Please do not add another argument to createMessageNode(). We will remove this function as soon as possible.

However, I like the idea of a target argument for createLocationNode(), so keep that.

@@ +2372,5 @@
>  
>      // Add the message repeats node only when needed.
>      let repeatNode = null;
>      if (aCategory != CATEGORY_INPUT && aCategory != CATEGORY_OUTPUT &&
> +        aCategory != CATEGORY_NETWORK && aCategory != CATEGORY_CSS) {

This is going to break css message repeats detection. Please make sure repeatNode is not added only for reflow-related messages.

@@ +2394,5 @@
>      // Create the source location (e.g. www.example.com:6) that sits on the
>      // right side of the message, if applicable.
>      let locationNode;
>      if (aSourceURL && IGNORED_SOURCE_URLS.indexOf(aSourceURL) == -1) {
> +      locationNode = this.createLocationNode(aSourceURL, aSourceLine, aTarget);

This looks good but I think you can determine |aTarget| here based on message category, instead of adding the |aTarget| argument to the createMessageNode() function.

@@ +4836,5 @@
>     */
>    _attachConsole: function WCCP__attachConsole()
>    {
>      let listeners = ["PageError", "ConsoleAPI", "NetworkActivity",
> +                     "FileActivity", "ReflowActivity"];

Please start the ReflowActivity listener only when the csslog filter pref is enabled, and stop it when it's disabled.

https://developer.mozilla.org/en-US/docs/Tools/Web_Console/remoting#startListeners%28listeners.2C_onResponse%29

Comment 10

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

Comment on attachment 816623 [details] [diff] [review]
Patch v0.3

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

Sounds a good start.

Comment 11

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

Tim,
the reflow observer from bug 453650 is awesome and extremely helpful. Do you know if there is a way to provide more informations for all those reflows that does not have a stack, like the one that comes from CSS from example?

This will help a lot when debugging reflows issues on FirefoxOS and likely for the rest of the world as well.

Comment 12

[Paul Rouget [:paul]]

(In reply to Vivien Nicolas (:vingtetun) (:21) from comment #11)
> Tim,
> the reflow observer from bug 453650 is awesome and extremely helpful. Do you
> know if there is a way to provide more informations for all those reflows
> that does not have a stack, like the one that comes from CSS from example?
> 
> This will help a lot when debugging reflows issues on FirefoxOS and likely
> for the rest of the world as well.

What kind of info do you want exactly? Let's imagine the reflow is triggered by a user action:

div {
  margin:  0px;
}
div:hover {
  margin: 10px;
}

What kind of log do you see here?

Comment 13

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

(In reply to Paul Rouget [:paul] from comment #12)
> (In reply to Vivien Nicolas (:vingtetun) (:21) from comment #11)
> > Tim,
> > the reflow observer from bug 453650 is awesome and extremely helpful. Do you
> > know if there is a way to provide more informations for all those reflows
> > that does not have a stack, like the one that comes from CSS from example?
> > 
> > This will help a lot when debugging reflows issues on FirefoxOS and likely
> > for the rest of the world as well.
> 
> What kind of info do you want exactly? Let's imagine the reflow is triggered
> by a user action:
> 
> div {
>   margin:  0px;
> }
> div:hover {
>   margin: 10px;
> }
> 
> What kind of log do you see here?

Knowing that it comes from div:hover would be priceless. I can imagine that if reflows are batched, the first of the series that has triggered the reflows would be nice.

Comment 14

[Tim Taubert [:ttaubert] (inactive)]

Tracking synchronous reflows and trying to avoid them is one thing. Something else we should look into is some way of knowing why certain frames have been invalidated. That could be a :hover, some JS code changing CSS classes, etc.

Maybe we could include some devtool that would highlight elements that have been invalidated (a little like paint flashing) and would provide a list of events including why the element was invalidated?

Comment 15

[Paul Rouget [:paul]]

Attachment: Actors code - V1

Comment 16

[Paul Rouget [:paul]]

Attachment: Frontend code - V1

Comment 17

[Paul Rouget [:paul]]

Attachment: Test - V1

Comment 18

[Mihai Sucan [:msucan]]

Comment on attachment 817859 [details] [diff] [review]
Actors code - V1

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

Patch looks good. r+

::: toolkit/devtools/client/dbg-client.jsm
@@ +185,5 @@
>  const UnsolicitedNotifications = {
>    "consoleAPICall": "consoleAPICall",
>    "eventNotification": "eventNotification",
>    "fileActivity": "fileActivity",
> +  "reflowActivity": "reflowActivity",

nit: this is supposed to be an alphabetic list.

::: toolkit/devtools/webconsole/utils.js
@@ +2590,5 @@
>  };
>  
> +
> +/**
> + * A ReflowObserver that listens for reflow events from the page.

nit: please mention this is an nsIReflowObserver implementation.

@@ +2602,5 @@
> + */
> +
> +function ConsoleReflowListener(aWindow, aListener)
> +{
> +  this.docshell = aWindow.QueryInterface(Ci.nsIInterfaceRequestor).getInterface(Ci.nsIWebNavigation).QueryInterface(Ci.nsIDocShell);

nit: please wrap at 80 chars.

@@ +2614,5 @@
> +  QueryInterface: XPCOMUtils.generateQI([Ci.nsIReflowObserver, Ci.nsISupportsWeakReference]),
> +  docshell: null,
> +  listener: null,
> +
> +  sendReflow: function(start, end, interruptible) {

nit: for consistency with the rest of the file please use named functions, arguments with the "a" prefix, jsdoc comments, and new line before curly bracket.

Comment 19

[Mihai Sucan [:msucan]]

Comment on attachment 817860 [details] [diff] [review]
Frontend code - V1

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

Patch looks good. r+ with the comments below addressed.

::: browser/devtools/webconsole/webconsole.js
@@ +575,5 @@
>    /**
> +   * Attach / detach reflow listeners depending on the checked status
> +   * of the `CSS > Log` menuitem.
> +   */
> +  updateReflowActivityListener: function WCCP__updateReflowActivityListener() {

Please mark this method as private.

s/WCCP/WCF/

nit: new line before curly brace, for consistency.

@@ +761,5 @@
>          target.setAttribute("checked", state);
>  
>          let prefKey = target.getAttribute("prefKey");
>          this.setFilterState(prefKey, state);
> +        this.updateReflowActivityListener();

Maybe call updateReflowActivityListener() in setFilterState()?

@@ +1550,5 @@
>    {
>      this.outputMessage(CATEGORY_NETWORK, this.logFileActivity, [aFileURI]);
>    },
>  
> +  logReflowActivity: function WCF_logReflowActivity(aMessage)

Please add jsdoc comments to the new functions.

@@ +1555,5 @@
> +  {
> +    let {start, end, sourceURL, sourceLine} = aMessage;
> +    let duration = Math.round((end - start) * 100) / 100;
> +    let node = this.document.createElementNS(XHTML_NS, "span");
> +    if (sourceURL) {

How can I trigger a reflow with a link?

::: browser/locales/en-US/chrome/browser/devtools/webconsole.properties
@@ +88,5 @@
>  # using their type (from the constructor function) in this descriptive string.
>  # Parameters: %S is the object type.
>  gcliterm.instanceLabel=Instance of %S
>  
> +reflow.messageWithLink=reflow: %Sms\u0020

Maybe add a localization note for these new strings explaining when they show up.

Comment 20

[Mihai Sucan [:msucan]]

Comment on attachment 817861 [details] [diff] [review]
Test - V1

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

This is looking good. r+

Can you please also add a webconsole test in browser/ ? Thank you!

::: toolkit/devtools/webconsole/test/test_reflow.html
@@ +1,5 @@
> +<!DOCTYPE HTML>
> +<html lang="en">
> +<head>
> +  <meta charset="utf8">
> +  <title>Test for the Console API</title>

Please update the title to reflect the test's purpose.

@@ +34,5 @@
> +  client = aState.dbgClient;
> +
> +  onReflowActivity = onReflowActivity.bind(null, aState);
> +  client.addListener("reflowActivity", onReflowActivity);
> +  iter = generateReflow();

Is generateReflow() a function yields?

Comment 21

[Mihai Sucan [:msucan]]

> @@ +34,5 @@
> > +  client = aState.dbgClient;
> > +
> > +  onReflowActivity = onReflowActivity.bind(null, aState);
> > +  client.addListener("reflowActivity", onReflowActivity);
> > +  iter = generateReflow();
> 
> Is generateReflow() a function yields?

Is generateReflow() a function that yields?

Comment 22

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

Can we open a followup to have a stack when some JS code is triggering reflows by toggling a CSS class?

Comment 23

[Paul Rouget [:paul]]

Attachment: addendum

Mihai, I'll address all your comments in a combined patch. The 2 big changes are this addendum and the browser/webconsole test.

Comment 24

[Paul Rouget [:paul]]

And there's a type in the comment in the addendum. I'll fix that.

Comment 25

[Paul Rouget [:paul]]

Attachment: All-in-one

Addressed all the comments. Added the addendum with type fixed, and added a webconsole browser test.

Comment 26

[Paul Rouget [:paul]]

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

Comment 27

[Paul Rouget [:paul]]

Orange. I might need to force the reflow…

Comment 28

[Paul Rouget [:paul]]

Attachment: addendum 2

When testing this, we need to know when the page is actually listening to reflows. So once the observer is added, the actor send a {message:"listen-on"} packet.

Comment 29

[Paul Rouget [:paul]]

Attachment: All-in-one v2 (with new packets)

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

Comment 30

[Mihai Sucan [:msucan]]

Comment on attachment 819011 [details] [diff] [review]
addendum 2

I'm not sure this approach is the best approach. You should not need packet changes, or anything like 'listen-on'.

You have WCF__updateReflowActivityListener() which calls start/stopListener(), and you have the option to add a callback, the server already notifies the client when the reflow listener is started, with a response packet. You only need to add a second argument to startListener() in the aforementioned private method. You can do this.emit("listeners-started", responsePacket.startedListeners). From the test you can then do hud.ui.once("listeners-started", ...).

I believe it's all doable in the client, in a nicer way. Thank you!

Comment 31

[Paul Rouget [:paul]]

Addressed Mihai's comment: https://tbpl.mozilla.org/?tree=Try&rev=42fe5a91d975

Comment 32

[Paul Rouget [:paul]]

Attachment: All-in-one v3 (using listeners instead of new packet)

Mihai, if this turns green, maybe you want to r+ this patch again.

Comment 33

[Mihai Sucan [:msucan]]

Comment on attachment 819033 [details] [diff] [review]
All-in-one v3 (using listeners instead of new packet)

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

Patch looks good. Thanks for the update!

There's a typo in the patch commit message: s/r=mscucan/r=msucan/ please :)

Comment 34

[Paul Rouget [:paul]]

Attachment: patch with correct commit message

Comment 35

[Paul Rouget [:paul]]

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

Comment 36

[Paul Rouget [:paul]]

Filed bug 929469: Show why layout has been invalidated.

Comment 37

[Paul Rouget [:paul]]

Still orange. Damnit.

Comment 38

[Paul Rouget [:paul]]

Attachment: final patch

This should do it.

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

Comment 39

[Ed Morley [:emorley]]

https://hg.mozilla.org/integration/fx-team/rev/18684ec60867

Comment 40

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/18684ec60867

Comment 41

[Petruta Horea [:phorea], Desktop QA]

Feature signed-off on Firefox 27.0a2 (20131128004001), tested on the next OSs: Windows 7 64bit, Windows 8 32bit, Ubuntu 13.04 32bit, Mac OSX 10.8.5, Firefox OS 1.3.0.0-prerelease (on an unagi device).

Comment 42

[Benoit Girard (:BenWa)]

This is showing up in profiles, see CRL_reflowInterruptible() @ utils.js:
http://people.mozilla.org/~bgirard/cleopatra/#report=c39094f56267ab0999b67915ba91205152211875

I don't have any devtools/app manager or anything of that sort attached.

Can we not have this run when we don't have anything listening?

Comment 43

[Paul Rouget [:paul]]

(In reply to Benoit Girard (:BenWa) from comment #42)
> This is showing up in profiles, see CRL_reflowInterruptible() @ utils.js:
> http://people.mozilla.org/~bgirard/cleopatra/
> #report=c39094f56267ab0999b67915ba91205152211875
> 
> I don't have any devtools/app manager or anything of that sort attached.
> 
> Can we not have this run when we don't have anything listening?

I'm not sure how to read your graph, but are you saying that we still listen to reflows when the devtools are not running?

Comment 44

[Benoit Girard (:BenWa)]

(In reply to Paul Rouget [:paul] (slow to respond. Ping me on IRC) from comment #43)
> I'm not sure how to read your graph, but are you saying that we still listen
> to reflows when the devtools are not running?

Yes, we're paying the performance cost. I noticed that now enabling the FPS counter incorrectly requires turning on the developer HUD from the Developer tab so that may be why we're seeing this show up.

Comment 45

[Paul Rouget [:paul]]

Jan, can you look at this? I think you fixed this recently.

Comment 46

[Jan Keromnes [:janx]]

Yes, I explained that particular regression to Benoit in bug 987951 comment 15, and fixed it in bug 989272 by allowing control over the FPS and TTL monitors independently from the Developer HUD (the fix landed in Gaia about 30h ago).

Comment 47

[Benoit Girard (:BenWa)]

Sounds good to me