[wasm][windows] v8 doesn't seem to exit sometimes causing helix test run to time out

[radical]

Two recent instances of this seen on rolling builds:

System.Text.RegularExpressions.Generators.Tests

01:04:48] info: Received expected 378 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[01:04:48] info: Finished writing 378 bytes of RESULTXML
[01:04:48] info: Xml file was written to the provided writer.
[01:04:48] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-System.Text.RegularExpressions.Generators.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests

[23:13:33] info: Received expected 387 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[23:13:33] info: Finished writing 387 bytes of RESULTXML
[23:13:33] info: Xml file was written to the provided writer.
[23:13:33] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

cc @pavelsavara @radekdoulik

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

Issue Details

---

Two recent instances of this seen on rolling builds:

System.Text.RegularExpressions.Generators.Tests

01:04:48] info: Received expected 378 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[01:04:48] info: Finished writing 378 bytes of RESULTXML
[01:04:48] info: Xml file was written to the provided writer.
[01:04:48] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-System.Text.RegularExpressions.Generators.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests

[23:13:33] info: Received expected 387 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[23:13:33] info: Finished writing 387 bytes of RESULTXML
[23:13:33] info: Xml file was written to the provided writer.
[23:13:33] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

cc @pavelsavara

Author:	radical
Assignees:	-
Labels:	arch-wasm
Milestone:	-

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

[lewing]

That sounds like the task queue isn't empty, @maraf could you take a look at this.

Tagging subscribers to this area: @directhex
See info in area-owners.md if you want to be subscribed.

Issue Details

---

Two recent instances of this seen on rolling builds:

System.Text.RegularExpressions.Generators.Tests

01:04:48] info: Received expected 378 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[01:04:48] info: Finished writing 378 bytes of RESULTXML
[01:04:48] info: Xml file was written to the provided writer.
[01:04:48] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-System.Text.RegularExpressions.Generators.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests

[23:13:33] info: Received expected 387 of C:\helix\work\workitem\uploads\xharness-output\testResults.xml
[23:13:33] info: Finished writing 387 bytes of RESULTXML
[23:13:33] info: Xml file was written to the provided writer.
[23:13:33] info: Tests run: 0 Passed: 0 Inconclusive: 0 Failed: 0 Ignored: 0 Skipped: 0

...
[EXECUTION TIMED OUT]
Exit Code:-3Executor timed out after 3600 seconds and was killed

['normal-Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests' END OF WORK ITEM LOG: Command timed out, and was killed]

cc @pavelsavara @radekdoulik

Author:	radical
Assignees:	maraf
Labels:	arch-wasm, area-Infrastructure-mono
Milestone:	7.0.0

[maraf]

Some findings

• Windows AOT and v8 only (other scenarios don't run on Windows AOT).
• 0 tests run in both projects.
• I'm not able compile those tests locally with AOT, but when I pick a smaller assembly (like System.ValueTuple.Tests), it creates some delay (10-15s) after "Tests run: ..." and before XHarness actually exits.
  • It is a place where v8 (and wasm) exists and returns to XHarness cli.
• It happens even locally
  • dotnet.wasm has 405MB for Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests.
  • It doesn't timeout, but takes few minutes to exit after tests are finished.
  • It is v8 specific, other scenarios don't have the delay.
  • Even when .NET main is not executed from javascript, the delay is still there.

[radical]

Hit again on a rolling build - https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-06a2b5c99cde42688b/normal-System.Text.RegularExpressions.Generators.Tests.Attempt.3/1/console.4a785ba6.log?sv=2019-07-07&se=2022-02-23T22%3A27%3A38Z&sr=c&sp=rl&sig=X5CSYRGPDL3DzCbQ4y88vWxCAUcnwQoNydZLyQ4ReSg%3D

[pavelsavara]

I saw similar behavior on local build with broken wasm binary. I think some wasm code was running tight loop over some data.
I think in my case it was pointer to char* which pointed to DLL metadata instead of the string I wanted to convert from utf8. So the time was linear with size of the data.
I recommend to try to use profiler or attach debugger to see what is running.
Also allocation patter could be useful. If it's allocating something in JS, it means it's running JS. Otherwise it could be just wasm loop.

[ilonatommy]

I saw similar behavior on local build with broken wasm binary. I think some wasm code was running tight loop over some data. I think in my case it was pointer to char* which pointed to DLL metadata instead of the string I wanted to convert from utf8. So the time was linear with size of the data. I recommend to try to use profiler or attach debugger to see what is running. Also allocation patter could be useful. If it's allocating something in JS, it means it's running JS. Otherwise it could be just wasm loop.

@maraf, this suggestion sounds helpful, have you tried it? What's the result?

[maraf]

• System.Text.RegularExpressions.Generators.Tests is skipped on browser. Originally all tests were marked to be skipped on browser and then whole test unit was excluded [wasm] Disable System.Text.RegularExpressions.Generators.Tests  #65238.
• Microsoft.Extensions.Logging.Generators.Roslyn3.11.Tests has been moved to "HighAOTResourceRequiringProject" in [wasm][aot] Run the high resource AOT tests on build machine itself #67017 and since then it doesn't fail.