1868960 - eventPageIdleResult fires at high rate and spams disk I/O

Status: RESOLVED FIXED

(WebExtensions :: General, defect, P1)

Description

[Tatsuyuki Ishi]

Attachment: stack1.txt

Steps to reproduce:

The issue was observed on 07b97216e7e3c16340c624f786e6d4b5f53ac6ea but I also experienced this issue in earlier versions.

When I disable the Tampermonkey extension, this issue disappears. However, with a clean profile, I could not reproduce the issue even if I install Tampermonkey and import settings.

Actual results:

The eventPageIdleResult event seems to be firing in a busy loop. This event triggers a counter update, and the high rate of event causes up to hundreds MB/s of disk write from glean.dispatcher thread (can be seen with iotop).

Attached are stacks that appears to correspond to the repeatedly firing telemetry update.

Expected results:

No telemetry should fire in what appears to be a busy loop.

Comment 1

[Tatsuyuki Ishi]

Attachment: stack2.txt

Comment 2

[Chris H-C :chutten]

Redirecting to WebExtensions where the instrumentation was added. I'm not sure that eventPageIdleResult is intended to be called frequently.

Comment 3

[BugBot [:suhaib / :marco]]

:rpl, since you are the author of the regressor, bug 1787940, could you take a look? Also, could you set the severity field?

For more information, please visit BugBot documentation.

Comment 4

[Rob Wu [:robwu]]

The actual regression is bug 1844041, which triggers this code path more often. In fact, for every API call.
The frequency of the telemetry recording is probably not very intentional.

If we want to fix the regression ASAP without having to back out bug 1844041 entirely, then we could skip the telemetry entirely for the reset_parentapicall, at https://searchfox.org/mozilla-central/rev/23e7e940337d0e0b29aabe0080e4992d3860c940/toolkit/components/extensions/parent/ext-backgroundPage.js#839-841

Longer-term we should optimize the event page keepalive to be more efficient than the quick fix that we implemented in bug 1844041.

Comment 5

[Shane Caraveo (:mixedpuppy)]

[Tracking Requested - why for this release]: Given the frequency of hits this code gets, we are going to quickly disable the telemetry in it and investigate alternatives later. We would like to get this into 121 so requesting tracking. The team will analyze Monday Dec 11 and assign.

Comment 6

[Rob Wu [:robwu]]

Attachment: Bug 1868960 - Disable reset_event and reset_parentapicall telemetry

Comment 7

[Shane Caraveo (:mixedpuppy)]

Comment on attachment 9367734 [details]
Bug 1868960 - Disable reset_event and reset_parentapicall telemetry

Beta/Release Uplift Approval Request

• User impact if declined: Pre-existing telemetry code ended up being in a hot path after more recent changes landing in 121 causing noticeable performance issues for users. This uplift will prevent those issues for users on release.
• Is this code covered by automated tests?: Yes
• Has the fix been verified in Nightly?: No
• Needs manual test from QE?: No
• If yes, steps to reproduce:
• List of other uplifts needed: None
• Risk to taking this patch: Low
• Why is the change risky/not risky? (and alternatives if risky): This simply shortcuts the code path prior to the telemetry call for the hot paths.
• String changes made/needed: None
• Is Android affected?: Yes

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b94618206c5c
Disable reset_event and reset_parentapicall telemetry r=willdurand

Comment 9

[Tatsuyuki Ishi]

I can confirm that the I/O is much more toned down with the patch applied.

Comment 10

[Iulian Moraru]

https://hg.mozilla.org/mozilla-central/rev/b94618206c5c

Comment 11

[Tatsuyuki Ishi]

After running with the patch for a few more hours I've noticed that there were still periodic slowdowns, just without the disk flood.

I think there's a bug in Tampermonkey that causes it to do something in background worker indefinitely, which was exacerbated by the change that allows background workers to run forever. I've reinstalled the extension and the problem is gone for now.

Performance issues related to WebExtension background activity seems very hard to track down, because all load is crammed into a single process called "WebExtensions". I could only have pinned this down because I noticed a strong side effect of it (disk flood) and placed a breakpoint to its call right in the debugger. Performance observability for WebExtensions might be a candidate for future improvement.

Comment 12

[Rob Wu [:robwu]]

(In reply to Tatsuyuki Ishi from comment #11)

After running with the patch for a few more hours I've noticed that there were still periodic slowdowns, just without the disk flood.

The specific issue reported here is related to having many extension API calls in a short succession. There are two bugs: extensions shouldn't do that indefinitely, and Firefox should not have too much overhead in handling extension API calls. The latter has been addressed with the patch above.

I think there's a bug in Tampermonkey that causes it to do something in background worker indefinitely,

I have seen reports in the wild of such bugs. For example https://github.com/Tampermonkey/tampermonkey/issues/1921

Performance observability for WebExtensions might be a candidate for future improvement.

Profiler.firefox.com can be used to measure the cause of the perceived performance issue. If you see an issue with Firefox, open a new bug with a link to the shared profile.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 9367734 [details]
Bug 1868960 - Disable reset_event and reset_parentapicall telemetry

Approved for 121.0rc1.

Comment 14

[Pulsebot]

https://hg.mozilla.org/releases/mozilla-beta/rev/fa79ec82fba4