[wasm] Reduce number of calls to setTimer #62433

pavelsavara · 2021-12-06T14:44:03Z

Problem description

When each new timer‡ is created it would start self-sustaining setTimeout loop.
The loop instance would only stop when ALL timers are done.
Many scheduled loops could be running in parallel to each other.
I added calls to mono_set_timeout_exec in Net6.0 to prevent timer throttling. That made the underlying problem worse and that's how it was detected.

‡ TimerQueue is group of timers, so only shorter than current in the same TimerQueue does that.

Fix

changes in TimerQueue.Browser.Mono.cs
- we will always have only one, the shortest due setTimeout pending for all TimerQueue instances.
- we remember it's due time in global s_shortestDueTimeMs
- we will not schedule new setTimeout if current pending is earlier than requested one . Even from different TimerQueue instance.
- if there is new timer which need to be scheduled earlier than the existing one, we would clear the previous one and register new one. Replace, rather than add the loop.
changes in scheduling.ts
- fix of negated condition bug prevent_timer_throttling, only introduced in Net7.0
- removed support for engines without setTimeout for better code readability. Removed timeout_queue.
- added lastSchedule which is the previous registration of pending timer. We call clearTimeout on it, any time new timer is registered.

Testing

on V8 setTimeout ignores delay and behaves as it was always 0. V8 could not be used to test timers.
created simple test which could be executed on NodeJS console.
the test would monkey patch globalThis.setTimeout to be able to observe number of setTimeout calls and number of callback executions.
it covers few basic test scenarios with expectations on number of calls mono does

Fix for #62227

TODO

run the repro
Test with prevent_timer_throttling
Backport to Net6.0 - [wasm][release/6.0] Reduce number of calls to setTimer #62705

ghost · 2021-12-06T14:44:10Z

Tagging subscribers to 'arch-wasm': @lewing
See info in area-owners.md if you want to be subscribed.

Issue Details

work in progress

Trying fix #62227

Author:	pavelsavara
Assignees:	-
Labels:	`arch-wasm`
Milestone:	-

...ime.InteropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/TimerTests.cs

src/mono/System.Private.CoreLib/src/System/Threading/TimerQueue.Browser.Mono.cs

src/mono/wasm/runtime/scheduling.ts

pavelsavara · 2021-12-08T01:07:04Z

/azp run runtime-manual

azure-pipelines · 2021-12-08T01:07:21Z

Azure Pipelines successfully started running 1 pipeline(s).

src/mono/wasm/runtime/scheduling.ts

...eropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/Simple/TimerTests.cs

pavelsavara · 2021-12-08T11:27:28Z

This is test with the repro sample, when running this PR (net 7.0)

It shows that

prevent_timer_throttling would hit every second and steal the work from the next timer
every other hit is just mono_wasm_set_timeout_exec of the 500ms Timer in the repro code

blazor.webassembly.js:1         Delay 00:00:00.5040000 avg rate 00:00:00.5012456
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.4970000 avg rate 00:00:00.5011724
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.4960000 avg rate 00:00:00.5010847
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.5100000 avg rate 00:00:00.5012333
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.4900000 avg rate 00:00:00.5010492
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.5050000 avg rate 00:00:00.5011129
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.5010000 avg rate 00:00:00.5011111
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message

Current code on Net6.0 has hundred calls to mono_wasm_set_timeout_exec each tick.

When the page is out of focus and the browser applies timer throttling

the timer rate is 1 second
we see the call triggered by prevent_timer_throttling doing all the work
followed by mono_set_timeout loop immediately, just once

blazor.webassembly.js:1         Delay 00:00:00.9930000 avg rate 00:00:00.5299002
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.9960000 avg rate 00:00:00.5310047
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.0030000 avg rate 00:00:00.5297565
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.9970000 avg rate 00:00:00.5308585
dotnet.6.0.0.siibt7wbrl.js:3373 prevent_timer_throttling cb
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.0020000 avg rate 00:00:00.5296141
dotnet.6.0.0.siibt7wbrl.js:3352 pump_message
dotnet.6.0.0.siibt7wbrl.js:3355 mono_background_exec
dotnet.6.0.0.siibt7wbrl.js:3389 mono_wasm_set_timeout_exec
dotnet.6.0.0.siibt7wbrl.js:3387 mono_set_timeout
blazor.webassembly.js:1         Delay 00:00:00.9960000 avg rate 00:00:00.5307089

pavelsavara · 2021-12-08T11:30:31Z

cc @m-chandler

...eropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/Simple/TimerTests.cs

pavelsavara · 2021-12-09T12:45:28Z

/azp run runtime-manual

azure-pipelines · 2021-12-09T12:45:42Z

Azure Pipelines successfully started running 1 pipeline(s).

Co-authored-by: Marek Fišera <[email protected]>

pavelsavara · 2021-12-09T15:06:35Z

/azp run runtime-manual

azure-pipelines · 2021-12-09T15:06:48Z

Azure Pipelines successfully started running 1 pipeline(s).

...ime.InteropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/TimerTests.cs

kg

This all looks right to me.

Test is only manual. Xharness version on this branch triggers timer queue in a way that makes the test useless. Co-authored-by: Pavel Savara <[email protected]>

* Port changes to the TimerQueue from #62433. Test is only manual. Xharness version on this branch triggers timer queue in a way that makes the test useless. Co-authored-by: Pavel Savara <[email protected]> * Replace main method with plain static method for running timer tests. * Rename index.html to simple.html to avoid collision with generated index.html for unit tests. Co-authored-by: Pavel Savara <[email protected]>

pavelsavara added the arch-wasm WebAssembly architecture label Dec 6, 2021

pavelsavara requested a review from kg December 6, 2021 14:44

ghost added the area-System.Runtime.InteropServices.JavaScript label Dec 6, 2021

pavelsavara force-pushed the wasm_fix_timers branch from 89c2894 to dc877ce Compare December 6, 2021 17:44

kg reviewed Dec 6, 2021

View reviewed changes

...ime.InteropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/TimerTests.cs Outdated Show resolved Hide resolved

kg reviewed Dec 6, 2021

View reviewed changes

src/mono/System.Private.CoreLib/src/System/Threading/TimerQueue.Browser.Mono.cs Outdated Show resolved Hide resolved

kg reviewed Dec 6, 2021

View reviewed changes

src/mono/wasm/runtime/scheduling.ts Show resolved Hide resolved

runfoapp bot mentioned this pull request Dec 6, 2021

System.Net.Sockets.Tests.SendPacketsAsync.SendPacketsElement_FileZeroCount_Success sometimes fails #60017

Closed

pavelsavara force-pushed the wasm_fix_timers branch 2 times, most recently from 4883d89 to 6ce3dbe Compare December 8, 2021 01:01

pavelsavara force-pushed the wasm_fix_timers branch from 6ce3dbe to 20b4d87 Compare December 8, 2021 08:05

pavelsavara requested a review from maraf December 8, 2021 08:06

pavelsavara added this to the 6.0.x milestone Dec 8, 2021

pavelsavara requested review from vargaz and akoeplinger December 8, 2021 08:23

maraf reviewed Dec 8, 2021

View reviewed changes

src/mono/wasm/runtime/scheduling.ts Outdated Show resolved Hide resolved

...eropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/Simple/TimerTests.cs Outdated Show resolved Hide resolved

pavelsavara requested a review from kg December 8, 2021 10:40

pavelsavara marked this pull request as ready for review December 8, 2021 11:29

pavelsavara requested a review from marek-safar as a code owner December 8, 2021 11:29

maraf reviewed Dec 8, 2021

View reviewed changes

...eropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/Simple/TimerTests.cs Outdated Show resolved Hide resolved

pavelsavara force-pushed the wasm_fix_timers branch from 54719e4 to ee274a0 Compare December 9, 2021 14:59

pavelsavara added 2 commits December 9, 2021 16:02

wip

68168ba

no id

927a027

pavelsavara and others added 7 commits December 9, 2021 16:02

feedback

9bb2585

cleanup

f693c9a

cleanup

ac3fb95

typo

cc45045

Co-authored-by: Marek Fišera <[email protected]>

switch to new xunit/xharness

29b37a2

improve test

26e2b49

only on browser, make less noise

b71b244

pavelsavara force-pushed the wasm_fix_timers branch from ee274a0 to b71b244 Compare December 9, 2021 15:02

vargaz approved these changes Dec 9, 2021

View reviewed changes

kg reviewed Dec 10, 2021

View reviewed changes

...ime.InteropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/TimerTests.cs Outdated Show resolved Hide resolved

kg reviewed Dec 10, 2021

View reviewed changes

...ime.InteropServices.JavaScript/tests/System/Runtime/InteropServices/JavaScript/TimerTests.cs Outdated Show resolved Hide resolved

kg approved these changes Dec 10, 2021

View reviewed changes

maraf approved these changes Dec 10, 2021

View reviewed changes

feedback

df27bdc

pavelsavara merged commit 806a06e into dotnet:main Dec 10, 2021

maraf mentioned this pull request Dec 13, 2021

[wasm][release/6.0] Reduce number of calls to setTimer #62705

Merged

2 tasks

pavelsavara deleted the wasm_fix_timers branch January 4, 2022 13:06

ghost locked as resolved and limited conversation to collaborators Feb 3, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

[wasm] Reduce number of calls to setTimer #62433

[wasm] Reduce number of calls to setTimer #62433

Uh oh!

pavelsavara commented Dec 6, 2021 •

edited

Loading

Uh oh!

ghost commented Dec 6, 2021

Uh oh!

Uh oh!

Uh oh!

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

azure-pipelines bot commented Dec 8, 2021

Uh oh!

Uh oh!

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

Uh oh!

pavelsavara commented Dec 9, 2021

Uh oh!

azure-pipelines bot commented Dec 9, 2021

Uh oh!

pavelsavara commented Dec 9, 2021

Uh oh!

azure-pipelines bot commented Dec 9, 2021

Uh oh!

Uh oh!

Uh oh!

kg left a comment

Uh oh!

Uh oh!

[wasm] Reduce number of calls to setTimer #62433

[wasm] Reduce number of calls to setTimer #62433

Uh oh!

Conversation

pavelsavara commented Dec 6, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Problem description

Fix

Testing

TODO

Uh oh!

ghost commented Dec 6, 2021

Uh oh!

Uh oh!

Uh oh!

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

azure-pipelines bot commented Dec 8, 2021

Uh oh!

Uh oh!

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

pavelsavara commented Dec 8, 2021

Uh oh!

Uh oh!

pavelsavara commented Dec 9, 2021

Uh oh!

azure-pipelines bot commented Dec 9, 2021

Uh oh!

pavelsavara commented Dec 9, 2021

Uh oh!

azure-pipelines bot commented Dec 9, 2021

Uh oh!

Uh oh!

Uh oh!

kg left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

pavelsavara commented Dec 6, 2021 •

edited

Loading