1770658 - Don't wake up the Timer thread when adding a 0ms timer

Status: NEW

(Core :: XPCOM, enhancement)

Description

[Florian Quèze [:florian]]

In this long profile https://share.firefox.dev/3lwPxMD, on the parent process timer thread, there are 68 AddTimer markers for 0ms timers. I found them using filteredMarkers.filter(m=>m.data.delay==0) in the browser console.

The most frequent one by far is ParticularProcessPriorityManager from the code at https://searchfox.org/mozilla-central/rev/70cf6863bd85af2a3188ec1fe5209a3ec1b2de86/dom/ipc/ProcessPriorityManager.cpp#729-746 (the pref value is 0 except on Nightly on Android: https://searchfox.org/mozilla-central/rev/70cf6863bd85af2a3188ec1fe5209a3ec1b2de86/modules/libpref/init/StaticPrefList.yaml#2618-2634)

Adding these 0ms timers causes a wake up of the Timer thread every time: https://share.firefox.dev/3wEG4br

I think it should be easy to avoid the wake-up when the timer is 0, by just putting a runnable directly at the end of the event queue of the target thread.

Comment 1

[Florian Quèze [:florian]]

This profile has many more 0ms timers: https://share.firefox.dev/38v9DnE
This seems to come from this file https://searchfox.org/mozilla-central/rev/7751fef9eeb3db0a07ae4680daa2a62bd8f49882/toolkit/modules/subprocess/subprocess_worker_unix.js#621 which has 3 setTimeout(this.loop.bind(this), 0); lines.

Comment 2

[Justin Link]

Attachment: Bug 1770658 - Fire zero-delay timers right away r=florian

Comment 3

[Justin Link]

I have spent a pretty decent amount of time looking into creating a unit test to verify this new behavior. Testing this change requires checking a specific detail regarding when something occurs inside of TimerThread. While this should be possible, I haven't been able to figure out a how to mock things up such that I can verify that the expected action occurs at the expected time. Again, I'm sure that it's possible with some amount of work but it's probably not worth the effort.

Comment 4

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/9f0d0ce9c0df
Fire zero-delay timers right away r=florian

Comment 5

[Iulian Moraru]

Backed out or causing dt failures on browser_aboutdebugging_devtoolstoolbox_reload.js.
Before re-landing this please take a look at the bugs from the "Regressions" section. For now, I will mark them as fixed because of this backout.

• Push with failures

• Backfill range and retriggers that point at this as the culprit

• Failure log

• Backout link

[task 2023-02-25T11:54:35.772Z] 11:54:35     INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_reload.js | about:devtools-toolbox is still selected - 
[task 2023-02-25T11:54:35.773Z] 11:54:35     INFO - Check whether about:devtools-toolbox page displays correctly
[task 2023-02-25T11:54:35.773Z] 11:54:35     INFO - Buffered messages finished
[task 2023-02-25T11:54:35.774Z] 11:54:35     INFO - TEST-UNEXPECTED-FAIL | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_reload.js | about:devtools-toolbox page displays correctly - 
[task 2023-02-25T11:54:35.774Z] 11:54:35     INFO - Stack trace:
[task 2023-02-25T11:54:35.774Z] 11:54:35     INFO - chrome://mochikit/content/browser-test.js:test_ok:1465
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_reload.js:testReloadAboutDevToolsToolbox:70
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochitests/content/browser/devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_reload.js:null:34
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochikit/content/browser-test.js:handleTask:1037
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochikit/content/browser-test.js:_runTaskBasedTest:1109
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1251
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1026
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/<:1036
[task 2023-02-25T11:54:35.775Z] 11:54:35     INFO - Close about:devtools-toolbox page
[task 2023-02-25T11:54:35.776Z] 11:54:35     INFO - Wait for removeTab
[task 2023-02-25T11:54:35.776Z] 11:54:35     INFO - Removing tab.
[task 2023-02-25T11:54:35.776Z] 11:54:35     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2023-02-25T11:54:35.777Z] 11:54:35     INFO - Got event: 'TabClose' on [object XULElement].
[task 2023-02-25T11:54:35.777Z] 11:54:35     INFO - Tab removed and finished closing
[task 2023-02-25T11:54:35.777Z] 11:54:35     INFO - Wait for toolbox destroyed
[task 2023-02-25T11:54:35.816Z] 11:54:35     INFO - Wait until aboutdebugging is selected
[task 2023-02-25T11:54:35.816Z] 11:54:35     INFO - Wait until about:devtools-toolbox is removed from debug targets
[task 2023-02-25T11:54:35.823Z] 11:54:35     INFO - GECKO(2061) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2023-02-25T11:54:35.824Z] 11:54:35     INFO - GECKO(2061) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2023-02-25T11:54:35.826Z] 11:54:35     INFO - GECKO(2061) | JavaScript error: , line 0: NotFoundError: No such JSWindowActor 'DevToolsFrame'
[task 2023-02-25T11:54:35.830Z] 11:54:35     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2023-02-25T11:54:35.830Z] 11:54:35     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2023-02-25T11:54:35.831Z] 11:54:35     INFO - Console message: [JavaScript Error: "NotFoundError: No such JSWindowActor 'DevToolsFrame'"]
[task 2023-02-25T11:54:36.430Z] 11:54:36     INFO - Removing tab.
[task 2023-02-25T11:54:36.431Z] 11:54:36     INFO - Waiting for event: 'TabClose' on [object XULElement].
[task 2023-02-25T11:54:36.434Z] 11:54:36     INFO - Got event: 'TabClose' on [object XULElement].
[task 2023-02-25T11:54:36.442Z] 11:54:36     INFO - Tab removed and finished closing
[task 2023-02-25T11:54:36.451Z] 11:54:36     INFO - opening about:debugging
[task 2023-02-25T11:54:36.451Z] 11:54:36     INFO - Adding a new tab with URL: about:debugging
[task 2023-02-25T11:54:36.626Z] 11:54:36     INFO - Tab added and finished loading
[task 2023-02-25T11:54:36.627Z] 11:54:36     INFO - Wait until Connect page is displayed
[task 2023-02-25T11:54:36.627Z] 11:54:36     INFO - Select This Firefox page
[task 2023-02-25T11:54:36.627Z] 11:54:36     INFO - Wait for requests to be complete
[task 2023-02-25T11:54:36.705Z] 11:54:36     INFO - Wait for runtime page to be rendered
[task 2023-02-25T11:54:37.221Z] 11:54:37     INFO - Open about:devtools-toolbox page
[task 2023-02-25T11:54:37.221Z] 11:54:37     INFO - TEST-PASS | devtools/client/aboutdebugging/test/browser/browser_aboutdebugging_devtoolstoolbox_reload.js | about:debugging tab target appeared - 

Comment 6

[Justin Link]

This change should be a nice improvement but isn't critical so, for the moment, I'm holding off on looking further into in order to finish up some other work.

Comment 7

[BugBot [:suhaib / :marco/ :calixte]]

There's a r+ patch which didn't land and no activity in this bug for 2 weeks.
:jlink, could you have a look please?
If you still have some work to do, you can add an action "Plan Changes" in Phabricator.
For more information, please visit auto_nag documentation.

Comment 8

[Justin Link]

I intend to make another attempt at landing this next week and will check to see if the above-mentioned regressions are still happening.

Comment 9

[Justin Link]

Contrary to my earlier assertion, I won't be re-submitting this patch as-is because, having given this some more thought, I realized that this change could result in timers firing out of order.
To see this, consider the following scenario: We have two timers, 'A' and 'B', in our timer list, set to fire at times 't - e' and 't + e' respectively. At time 't' we insert a timer, 'C', that is supposed to fire immediately, however we have not yet fired timer 'A'. (The reason why we haven't fired 'A' yet could be timer coalescing or possibly simply because the operating system has woken us up yet.) If we fire 'C' immediately without taking this into account, 'C' would fire before 'A' which is incorrect.
This problem could be avoided if, when adding a timer and deciding that we can fire it immediately, we additionally look through the pending timer list and process any timers that are currently able to be fired (firing the new timer at the appropriate point). I will probably give this a shot at some point but, as the code for peeling off and firing timers is currently both very messy and embedded in TimerThread::Run(), doing this without making a total mess would require a bit of refactoring.