System.Text.RegularExpressions.Tests JitMinOpts only timeout

[BruceForstall]

----- start 19:14:03.62 ===============  To repro directly: ===================================================== 
pushd C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\tests\System.Text.RegularExpressions.Tests\netcoreapp-Windows_NT-Release-arm64\
set COMPlus_TieredCompilation=0 
call C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\testhost\netcoreapp-Windows_NT-Release-arm64\dotnet.exe xunit.console.netcore.exe System.Text.RegularExpressions.Tests.dll  -xml testResults.xml -notrait Benchmark=true -notrait category=nonnetcoreapptests -notrait category=nonwindowstests  -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================

C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\tests\System.Text.RegularExpressions.Tests\netcoreapp-Windows_NT-Release-arm64>set COMPlus_TieredCompilation=0  

C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\tests\System.Text.RegularExpressions.Tests\netcoreapp-Windows_NT-Release-arm64>set COMPlus_JITMinOpts=1 

C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\tests\System.Text.RegularExpressions.Tests\netcoreapp-Windows_NT-Release-arm64>call C:\Users\robox\j\workspace\arm64_cross_c---f75df612\_\fx\bin\testhost\netcoreapp-Windows_NT-Release-arm64\dotnet.exe xunit.console.netcore.exe System.Text.RegularExpressions.Tests.dll  -xml testResults.xml -notrait Benchmark=true -notrait category=nonnetcoreapptests -notrait category=nonwindowstests  -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing 
xUnit.net console test runner (64-bit .NET Core)
Copyright (C) 2014 Outercurve Foundation.

Discovering: System.Text.RegularExpressions.Tests
Discovered:  System.Text.RegularExpressions.Tests
Starting:    System.Text.RegularExpressions.Tests
   System.Text.RegularExpressions.Tests.RegexMatchTests.Match_ExcessPrefix [FAIL]
      Timed out after 60000ms waiting for remote process 5512
      Expected: True
      Actual:   False
      Stack Trace:
         D:\j\workspace\arm64_cross_c---101bec61\_\fx\src\CoreFx.Private.TestUtilities\src\System\Diagnostics\RemoteExecutorTestBase.cs(308,0): at System.Diagnostics.RemoteExecutorTestBase.RemoteInvokeHandle.Dispose(Boolean disposing)
         D:\j\workspace\arm64_cross_c---101bec61\_\fx\src\CoreFx.Private.TestUtilities\src\System\Diagnostics\RemoteExecutorTestBase.cs(295,0): at System.Diagnostics.RemoteExecutorTestBase.RemoteInvokeHandle.Dispose()
         D:\j\workspace\arm64_cross_c---101bec61\_\fx\src\System.Text.RegularExpressions\tests\Regex.Match.Tests.cs(795,0): at System.Text.RegularExpressions.Tests.RegexMatchTests.Match_ExcessPrefix()
Finished:    System.Text.RegularExpressions.Tests

=== TEST EXECUTION SUMMARY ===
   System.Text.RegularExpressions.Tests  Total: 1498, Errors: 0, Failed: 1, Skipped: 0, Time: 197.040s
----- end 19:17:36.82 ----- exit code 1 ----------------------------------------------------------

Related: https://github.com/dotnet/coreclr/issues/17754

category:testing
theme:minopts
skill-level:intermediate
cost:medium

[kouvel]

This is also failing on x64 on several OSes in the coreclr repo's corefx test runs when tiering is enabled (equivalent to minopts for this test). Not sure if it's related to the arm64 failure, but it's not clear to me what the problem is on x64. Rough numbers from my machine:

corefx repo all regex tests -

• default
  • release: 2700 ms
  • debug: 2800 ms
• minopts
  • release: 6100 ms
  • debug: 3000 ms

just the Match_ExcessPrefix test (times in ms for each regex in test) -

• default
  • release coreclr + release corefx: 60, 60, 1000
  • debug coreclr + debug corefx: 840, 840, 840
• minopts
  • release coreclr + release corefx: 40, 40, 4600
  • debug coreclr + debug corefx: 840, 840, 840

I don't see any numbers close to 60 seconds and yet it's timing out. I noticed that if I add RegexOptions.Compiled, the last regex in the test is taking ~60000 ms to complete with release coreclr and release corefx (and 1000 ms with debug coreclr and debug corefx), but that option is not specified in the test.

[kouvel]

PR to temporarily disable test: dotnet/corefx#31500

[echesakov]

I investigated this timeout failure and I believe this is due to the fact that under debug and minopts JIT does not expand CORINFO_INTRINSIC_StringGetChar and instead emit call to COMString::GetCharAt helper in System.Text.RegularExpressions.RegexBoyerMoore:.ctor(ref,bool,bool,ref):this.

I did simple experiment and for optimized code I disabled ONLY expansion of CORINFO_INTRINSIC_StringGetChar in importer which brings up running time for System.Text.RegularExpressions.Tests.RegexMatchTests.Match_ExcessPrefix from 2s up to 550s (which is roughly the same time needed for the test to finish under JITMinOpts).

Another experiment showed that setting JitMinOptsName=System.Text.RegularExpressions.RegexBoyerMoore:.ctor(ref,bool,bool,ref):this is enough for this test to fail due to timeout out.

@dotnet/jit-contrib Is this supposed to be this way? This call to COMString::GetCharAt happens in a loop and according to PerfView takes 99.4 Inc %

I also attached JitDisasm in case if someone is interested to see what's going on.

optimized code dasm.txt
optimized code - forbid CORINFO_INTRINSIC_StringGetChar expansion dasm.txt
minopts dasm.txt

[BruceForstall]

The JIT wants to leave calls as calls, and not do the intrinsic optimization, during MinOpts. This seems completely reasonable. The test does pass, it's just super slow. That would be expected. Seems like we just need a way to bump the timeout of this test, significantly, under Minopts/debuggable code.

[AndyAyersMS]

This is perhaps and example where Tier0 should diverge from minopts?

[kouvel]

Is that an issue even when RegexOptions.Compiled is not specified? The test doesn't specify RegexOptions.Compiled and locally the test was running fairly quickly with debug coreclr and debug corefx. Only when I change the test to use RegexOptions.Compiled it was very slow, any idea why it would be failing in the CI?

[kouvel]

The test was disabled for the coreclr repo's "CoreFX Tests" job in dotnet/coreclr#19488, once this is fixed please re-enable the test.

[danmoseley]

@ViktorHofer fyi.

[stephentoub]

FYI, this test has been changed since this issue was opened.

[am11]

With engine SourceGenerated, same test has started to fail:

windows x64 - https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-1846899be12742d186/System.Text.RegularExpressions.Tests/1/console.a2979f90.log

    System.Text.RegularExpressions.Tests.RegexMatchTests.Match_ExcessPrefix(engine: SourceGenerated) [FAIL]
      Half-way through waiting for remote process.
      Memory load: 11
      ...
      Timed out at 9/22/2021 11:53:49 PM after 60000ms waiting for remote process.
      Wrote mini dump to: C:\h\w\99FC08C0\w\B18309D5\uploads\5588.fckw5zf0.h4d.dmp
      	Process ID: 5588
      	Handle: 1984
      	Name: dotnet
      	MainModule: C:\h\w\99FC08C0\p\dotnet.exe
      	StartTime: 9/22/2021 11:52:49 PM
      	TotalProcessorTime: 00:01:02.6718750

linux musl arm64 - https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-heads-main-ae9baf50200a4cdebf/System.Text.RegularExpressions.Tests/1/console.28be79eb.log

    System.Text.RegularExpressions.Tests.RegexMatchTests.Match_ExcessPrefix(engine: SourceGenerated) [FAIL]
      Half-way through waiting for remote process.
      Timed out at 9/23/2021 12:13:52 AM after 60000ms waiting for remote process.
      	Process ID: 259
      	Handle: 3160
      	Name: dotnet
      	MainModule: /root/helix/work/correlation/dotnet
      	StartTime: 9/23/2021 12:12:51 AM
      	TotalProcessorTime: 00:01:03.2400000