0.29ms uninterruptible reflow at _handleDOMChange@chrome://extensions/content/ext-browser-content.js:215:24

NEW
Unassigned
(NeedInfo from)

Status

defect
P2
normal
2 years ago
7 months ago

People

(Reporter: florian, Unassigned, NeedInfo)

Tracking

(Blocks 1 bug, {perf})

unspecified
Points:
---
Dependency tree / graph
Bug Flags:
qe-verify -

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [ohnoreflow][qf:p3:responsiveness][fxperf:p3]triaged)

Attachments

(1 attachment)

Here's the stack:

_handleDOMChange@chrome://extensions/content/ext-browser-content.js:215:24
handleDOMChange/this.resizeTimeout<@chrome://extensions/content/ext-browser-content.js:175:13
setTimeout_timer@resource://gre/modules/Timer.jsm:30:5


http://searchfox.org/mozilla-central/rev/baf47b352e873d4516d7656186d6d7c7447d3873/toolkit/components/extensions/ext-browser-content.js#215
      let background = doc.defaultView.getComputedStyle(body).backgroundColor;

A timer and a sync layout flush in there.
Component: Untriaged → WebExtensions: Untriaged
Product: Firefox → Toolkit
Flags: qe-verify?
Priority: -- → P2
Whiteboard: [ohnoreflow][qf][photon-performance] → [ohnoreflow][qf:p1][photon-performance]
Flags: needinfo?(kmaglione+bmo)
Whiteboard: [ohnoreflow][qf:p1][photon-performance] → [ohnoreflow][qf:p1][photon-performance], triaged
Priority: P2 → P3
Whiteboard: [ohnoreflow][qf:p1][photon-performance], triaged → [ohnoreflow][qf:p1][reserve-photon-performance], triaged
Flags: qe-verify? → qe-verify-
Whiteboard: [ohnoreflow][qf:p1][reserve-photon-performance], triaged → [ohnoreflow][qf:p2][reserve-photon-performance], triaged
Priority: P3 → P4
Keywords: perf
This appears to still be an issue.
Whiteboard: [ohnoreflow][qf:p2][reserve-photon-performance], triaged → [ohnoreflow][qf:p1][reserve-photon-performance], triaged
Whiteboard: [ohnoreflow][qf:p1][reserve-photon-performance], triaged → [ohnoreflow][qf:i60][qf:p1][reserve-photon-performance], triaged
Whiteboard: [ohnoreflow][qf:i60][qf:p1][reserve-photon-performance], triaged → [ohnoreflow][qf:f60][qf:p1][reserve-photon-performance], triaged
Whiteboard: [ohnoreflow][qf:f60][qf:p1][reserve-photon-performance], triaged → [ohnoreflow][qf:f61][qf:p1][reserve-photon-performance], triaged
Whiteboard: [ohnoreflow][qf:f61][qf:p1][reserve-photon-performance], triaged → [ohnoreflow][qf:f61][qf:p1][fxperf], triaged
As far as I can tell this causes a sync flush every time there's a DOM attribute/child/subtree (read: any) change anywhere in the document the webextension loads in the controlled browser (e.g. in browserAction or pageAction popups), throttled to every 100ms by a timer. Though, oddly, from what I can tell (and really, I'm assuming I'm reading this wrong, I just can't see how/why), when there's a change there will be a flush sync from the mutation observer being called, and then another flush 100ms later (but no more until those 100ms elapse).

In fact, I think the 100ms timeout doesn't work, either. Because we add the mutation observer (from the 'load' event) like this:

        // Mutation observer to make sure the panel shrinks when the content does.
        new content.MutationObserver(this.handleDOMChange.bind(this)).observe(
          content.document.documentElement, {
            attributes: true,
            characterData: true,
            childList: true,
            subtree: true,
          });

and handleDOMChange looks like this:

  // Resizes the browser to match the preferred size of the content (debounced).
  handleDOMChange(ignoreThrottling = false) {
    if (ignoreThrottling && this.resizeTimeout) {
      clearTimeout(this.resizeTimeout);
      this.resizeTimeout = null;
    }

    if (this.resizeTimeout == null) {
      this.resizeTimeout = setTimeout(() => {
        try {
          if (content) {
            this._handleDOMChange("delayed");
          }
        } finally {
          this.resizeTimeout = null;
        }
      }, RESIZE_TIMEOUT);

      this._handleDOMChange();
    }
  },

A mutation observer gets called with an array, which I think will be assigned to the 'ignoreThrottling' parameter here. An array is truthy, so we clear the timeout every time the mutation observer is called, then set a new one, then sync-call _handleDOMChange and do all the sync flushes via getBoundingClientRect and/or getComputedStyle. So TL;DR this will sync flush layout after every DOM change in the document in the browser (e.g. in browser popups).


All this seems... suboptimal, and possibly unintentional (based on the comments that suggest debouncing). Going to mark as fxperf:p2 because we don't have an assignee, but ideally I think this should be fixed sooner rather than later. So I'm going to be a little bit assertive and clear the priority field and ping :ddurst to get this on the webextension triage radar again. If everyone's swamped and/or I'm misreading this, feel free to set it back to P4 again, but I think it warrants looking at, at least.

(Going to clear :kmag's ni because I know he's busy and it's been 10 months so not sure it's super useful at this point.)
Component: WebExtensions: Untriaged → WebExtensions: Frontend
Flags: needinfo?(kmaglione+bmo) → needinfo?(ddurst)
Priority: P4 → --
Whiteboard: [ohnoreflow][qf:f61][qf:p1][fxperf], triaged → [ohnoreflow][qf:f61][qf:p1][fxperf:p2], triaged
Flags: needinfo?(ddurst) → needinfo?(lgreco)
I looked a bit about this uninterruptible reflow, and tried a number of strategies to prevent it,
the attached patch contains the minimal changes that seems to prevent the reflow but still pass all the existent popup tests,
apparently without making the intermittency of the popup tests higher (but I wouldn't be surprised if some of the popup tests, e.g. browser_ext_browserAction_popup_resize.js, still fail intermittently with these changes because of _handleDOMChange method turned into an async function).

To be fair, this reflow is going to happen on the main process browser UI only on the platforms where the extensions are not yet running in oop mode by default (currently only Linux), anyway I tried to reduce the chances of triggering an uninterruptible reflow from _handleDOMChange in both the oop and non oop extension modes.

After turning the _handleDOMChange method into an async function, I had to add some additional checks to prevent some of the webextensions tests to fail intermittently because of a popup document that has been destroyed between the time when _handleDOMChange has been called and once promiseDocumentFlushed is finally executing the callback and/or it has been resolved and the rest of _handleDOMChange is going to be executed.
It is probably worth to mention that some of these seems to already exist in form of intermittents / issues filed on bugzilla, e.g.

- Bug 1394010 - TypeError: content is null in ext-browser-content.js when extension popup changes DOM upon unload (triggers MutationObserver)
- Bug 1362770 - Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_popup_corners.js | Uncaught exception - TypeError: Argument 1 of Window.getComputedStyle is not an object.
- Bug 1379487 - Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_popup_background.js | Uncaught exception - TypeError: Argument 1 of Window.getComputedStyle is not an object.

promiseDocumentFlushed seems to only be available on privileged chrome window and a (non privileged) popup extension url is currently directly loaded in the remote browser, and so the attached patch is actually using promiseDocumentFlushed only when ext-browser-content.js when the extension popup is running in the main process (and so it can reach the root window XUL document from ext-browser-content.js).

I also tried to fix apply the necessary fixes for the issue mentioned by :Gijs in Comment 2 in this patch, and ensure that "handleDOMChange" is always called with ignoreThrottling set to false when called from the MutationObserver, unfortunately by doing it I've got an higher intermittency on some of the existent popup tests and so, given that it doesn't really solve the uninterruptible reflows that _handleDOMChange may trigger, I opted to defer it to a follow up.

While checking this reflow I also looked if we are triggering other uninterruptible reflows on the main process Firefox UI, and I noticed that the ViewPopup's attach function (defined in ExtensionPopups.jsm) is triggering another one pretty consistently from here:

- https://searchfox.org/mozilla-central/rev/8976abf9cab8eb4661665cc86bd355cd08238011/browser/components/extensions/ExtensionPopups.jsm#488,492

(I'll file a separate bug it directly from the dump produced using ohnoreflow, https://mikeconley.github.io/ohnoreflow/)
Flags: needinfo?(lgreco)
I just filed the other uninterruptible reflow triggered from ViewPopup's attach function as Bug 1446027.
See Also: → 1446027
Attachment #8959172 - Flags: review?(kmaglione+bmo)
Whiteboard: [ohnoreflow][qf:f61][qf:p1][fxperf:p2], triaged → [ohnoreflow][qf:f64][qf:p1][fxperf:p2], triaged
Whiteboard: [ohnoreflow][qf:f64][qf:p1][fxperf:p2], triaged → [ohnoreflow][qf:p1:f64][fxperf:p2]triaged
Product: Toolkit → WebExtensions
Priority: -- → P2
(not startup related: fxperf:p2 -> fxperf:p3)
Whiteboard: [ohnoreflow][qf:p1:f64][fxperf:p2]triaged → [ohnoreflow][qf:p1:f64][fxperf:p3]triaged
Whiteboard: [ohnoreflow][qf:p1:f64][fxperf:p3]triaged → [ohnoreflow][qf:p3:responsiveness][fxperf:p3]triaged

Looks like this has a patch with a pending review request from a while back -- I suspect it may have slipped off kmag's radar?

Flags: needinfo?(kmaglione+bmo)
You need to log in before you can comment on or make changes to this bug.