Runtime: Linq tests timing out in WASM leg

[danmosemsft]

Linq tests appear to be timing out (or possibly hanging) in WASM

https://dev.azure.com/dnceng/public/_build/results?buildId=780635&view=ms.vss-test-web.build-test-results-tab&runId=24492990&resultId=164319&paneView=dotnet-dnceng.dnceng-build-release-tasks.helix-test-information-tab
https://helixre107v0xdeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-41038-merge-558fe2197ef6431186/System.Linq.Tests/console.01a47de4.log?sv=2019-02-02&se=2020-09-09T20%3A59%3A51Z&sr=c&sp=rl&sig=Nv2ILnn693jzHBwsZrPiM8NJrLkYK7Qe2su3kYUaY78%3D

Executed on a003RYO
+ export PATH=/home/helixbot/work/A66808D0/p/dotnet:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
+ export DOTNET_ROOT=/home/helixbot/work/A66808D0/p/dotnet
+ export DOTNET_CLI_TELEMETRY_OPTOUT=1
+ export PATH=/home/helixbot/work/A66808D0/p/xharness-cli:/home/helixbot/work/A66808D0/p/dotnet:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
+ export XHARNESS_DISABLE_COLORED_OUTPUT=true
+ export XHARNESS_LOG_WITH_TIMESTAMPS=true
+ export XHARNESS_CLI_PATH=/home/helixbot/work/A66808D0/p/microsoft.dotnet.xharness.cli/1.0.0-prerelease.20411.1/tools/netcoreapp3.1/any/Microsoft.DotNet.XHarness.CLI.dll
+ ./RunTests.sh --runtime-path /home/helixbot/work/A66808D0/p
XHarness command issued: wasm test --engine=V8 --engine-arg=--stack-trace-limit=1000 --js-file=runtime.js -v --output-directory=./xharness-output -- --run WasmTestRunner.dll System.Linq.Tests.dll -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
[21:00:14] info: test[0]
      21:00:14.6178730 v8 --expose_wasm --stack-trace-limit=1000 runtime.js -- --run WasmTestRunner.dll System.Linq.Tests.dll -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing

[21:00:14] dbug: test[0]
      Arguments: --run,WasmTestRunner.dll,System.Linq.Tests.dll,-notrait,category=IgnoreForCI,-notrait,category=OuterLoop,-notrait,category=failing

[21:00:15] dbug: test[0]
      console.debug: MONO_WASM: Initializing mono runtime

[21:00:15] dbug: test[0]
      console.debug: MONO_WASM: ICU data archive(s) loaded, disabling invariant mode

[21:00:15] dbug: test[0]
      console.debug: mono_wasm_runtime_ready fe00e07a-5519-4dfe-b35a-f867dbaf2e28

[21:00:15] dbug: test[0]
      Initializing.....

[21:00:16] dbug: test[0]
      Discovering tests for System.Linq.Tests.dll
,...................

[21:15:10] dbug: test[0]
      [PASS] System.Linq.Tests.SkipLastTests.SkipLast(source: [0, 1, 2, 3, 4, ...], count: 8)

[21:15:12] dbug: test[0]
      [PASS] System.Linq.Tests.SkipLastTests.SkipLast(source: [0, 1, 2, 3, 4, ...], count: 13)

[21:15:13] dbug: test[0]
      [PASS] System.Linq.Tests.SkipLastTests.SkipLast(source: [0, 1, 2, 3, 4, ...], count: 21)

Killed

[msftbot[bot]]

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

[danmosemsft]

cc @steveisok

[CoffeeFlux]

Do we have any idea when this started? Would help narrow down the culprit.

[safern]

This is definitely a timeout because it is taking 15 mins to run and that's the helix timeout.

[danmosemsft]

@CoffeeFlux you could try mining Kusto, but it may simply be that it was always close to the timeout and the tests may need twiddling to make them less onerous in WASM runs.

[steveisok]

We should disable and link to this issue while we investigate.

[safern]

@steveisok I believe there are a few Linq tests that are disabled when we run against a checked coreclr which is slower than release and they were timing out. Had to step out from the computer but when I get a chance I can figure out which ones are there.

[danmosemsft]

I see these, I assume that's not what you mean: [ConditionalFact(typeof(TestEnvironment), nameof(TestEnvironment.IsStressModeEnabled))] enabled by COREFX_STRESS

[safern]

Hmm never mind, we skip the whole test assembly:

https://github.com/dotnet/runtime/blob/6072e4d3a7a2a1493f514cdf4be75a3d56580e84/src/libraries/System.Linq.Expressions/tests/AssemblyInfo.cs#L6

[CoffeeFlux]

Judging by https://github.com/dotnet/runtime/issues/12927 it seems the tests just take a long time and should probably be moved to outer loop only.

[steveisok]

Agreed

[steveisok]

If we want to OuterLoop the whole test project, we'll need to add Assembly to the valid declarations in https://github.com/dotnet/arcade/blob/master/src/Microsoft.DotNet.XUnitExtensions/src/Attributes/OuterLoopAttribute.cs

[akoeplinger]

It seems to only affect System.Linq.Tests, I can't find any System.Linq.Expression.Tests timeouts in the last week.

According to Kusto the majority of the 470 System.Linq test runs I looked at finish in under 7 mins (419 runs), but a good chunk takes up to 12-14mins longer and still passes (38 runs).

We should probably try increasing the timeout first.

[safern]

We should probably try increasing the timeout first.

@steveisok spoke about this and it seems like bumping to 17-18 mins would be reasonable. We somehow need a hook to do this in sendtohelix and also to flow it down to xharness since the xharness timeout is 15 mins as well.

[akoeplinger]

We should probably change the default xharness timeout too since I've seen runs of debug libraries locally that take >15mins.

[danmosemsft]

If it fails a few times a week with 15 mins then my guess is that 17-18 mins would still hit the tail of the distribution. Are there tests in there that are particularly long running that could be disabled for WASM? Presumably the chance of introducing a bug is low, because it would have to be something specific to those particular Linq codepaths and the interpreter. If only 5% of the tests take more than 5 mins, maybe they can be nixed for WASM.

[safern]

Maybe we can download a testResults.xml from a successful test run and look at which tests take long and disable those?

[steveisok]

Perhaps we should do both. Bump the timeout and outer loop some of the long running tests.

[danmosemsft]

Do any other libraries tests jobs on any configurations have > 15 min timeouts?

[safern]

Nope, only on coreclr stress but those are outerloop builds.

[steveisok]

I took a closer look at the Kusto data between a run that times out and a good run. It seems both have the same amount of records and their durations are ~13 min. I suspect a longer GC plays a part in the runs that time out. Wasm does not have the benefit of a separate GC thread.

I'm asking around if there are some GC knobs to tweak, but I feel like increasing the timeout might actually be the prudent choice.

[danmosemsft]

My reservation about increasing the timeout is that it potentially increases the time of our PR validation when it's not clear whether we're getting value in return. If I added some new Linq tests today, and it caused the full set to take 16 minutes on WASM, I wouldn't push another change to increase the timeout. I'd scale back the test. Is there any reason to believe that 15 mins isn't a reasonable quota to test all of Linq innerloop (on a machine that's not occupied with any other task) -- when no other library we have needs so long?

[steveisok]

Fair point. I mean, there is enough to send to the outerloop and potentially knob twist the gc.