Test failure: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll

[BruceForstall]

https://dev.azure.com/dnceng-public/public/_build/results?buildId=272907&view=ms.vss-test-web.build-test-results-tab

coreclr windows x86 Checked jitstress2_jitstressregs0x1000 @ Windows.10.Amd64.Open

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=0x1000

Looks like failure of this test brought down the whole run.

18:47:18.821 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll
App Exit Code: 3
Expected: 100
Actual: 3
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

A different run

coreclr windows x86 Checked jitstress2_jitstressregs1 @ Windows.10.Amd64.Open

with:

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=1

crashed:

18:57:33.193 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll

Assert failure(PID 3456 [0x00000d80], Thread: 4432 [0x1150]): !PreemptiveGCDisabled()

CORECLR! Thread::DetachThread + 0xCF (0x727a9aa5)
CORECLR! TlsDestructionMonitor::~TlsDestructionMonitor + 0x8F (0x72bf72f5)
CORECLR! _dyn_tls_dtor + 0x86 (0x72c099b6)
NTDLL! RtlDecompressBuffer + 0xDE (0x77aaea4e)
NTDLL! LdrShutdownThread + 0x386 (0x77a7eeb6)
NTDLL! LdrSetAppCompatDllRedirectionCallback + 0x1052A (0x77ad3c6a)
NTDLL! LdrShutdownProcess + 0x15F (0x77a92d7f)
NTDLL! RtlExitUserProcess + 0x96 (0x77a93886)
KERNEL32! ExitProcess + 0x13 (0x7795b3d3)
CORECLR! exit_or_terminate_process + 0x38 (0x72c43f08)
    File: D:\a\_work\1\s\src\coreclr\vm\threads.cpp Line: 979
    Image: C:\h\w\AA420919\p\corerun.exe

App Exit Code: -1073740286
Expected: 100
Actual: -1073740286
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

Another failure:

https://dev.azure.com/dnceng-public/public/_build/results?buildId=273272&view=ms.vss-test-web.build-test-results-tab

coreclr windows x86 Checked jitstress2_jitstressregs8 @ Windows.10.Amd64.Open

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=8

18:45:54.299 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll
App Exit Code: 3
Expected: 100
Actual: 3
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

@markples Another issue with merging?

cc @EgorBo

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

Issue Details

---

https://dev.azure.com/dnceng-public/public/_build/results?buildId=272907&view=ms.vss-test-web.build-test-results-tab

coreclr windows x86 Checked jitstress2_jitstressregs0x1000 @ Windows.10.Amd64.Open

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=0x1000

Looks like failure of this test brought down the whole run.

18:47:18.821 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll
App Exit Code: 3
Expected: 100
Actual: 3
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

A different run

coreclr windows x86 Checked jitstress2_jitstressregs1 @ Windows.10.Amd64.Open

with:

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=1

crashed:

18:57:33.193 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll

Assert failure(PID 3456 [0x00000d80], Thread: 4432 [0x1150]): !PreemptiveGCDisabled()

CORECLR! Thread::DetachThread + 0xCF (0x727a9aa5)
CORECLR! TlsDestructionMonitor::~TlsDestructionMonitor + 0x8F (0x72bf72f5)
CORECLR! _dyn_tls_dtor + 0x86 (0x72c099b6)
NTDLL! RtlDecompressBuffer + 0xDE (0x77aaea4e)
NTDLL! LdrShutdownThread + 0x386 (0x77a7eeb6)
NTDLL! LdrSetAppCompatDllRedirectionCallback + 0x1052A (0x77ad3c6a)
NTDLL! LdrShutdownProcess + 0x15F (0x77a92d7f)
NTDLL! RtlExitUserProcess + 0x96 (0x77a93886)
KERNEL32! ExitProcess + 0x13 (0x7795b3d3)
CORECLR! exit_or_terminate_process + 0x38 (0x72c43f08)
    File: D:\a\_work\1\s\src\coreclr\vm\threads.cpp Line: 979
    Image: C:\h\w\AA420919\p\corerun.exe

App Exit Code: -1073740286
Expected: 100
Actual: -1073740286
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

Another failure:

https://dev.azure.com/dnceng-public/public/_build/results?buildId=273272&view=ms.vss-test-web.build-test-results-tab

coreclr windows x86 Checked jitstress2_jitstressregs8 @ Windows.10.Amd64.Open

set DOTNET_TieredCompilation=0
set DOTNET_JitStress=2
set DOTNET_JitStressRegs=8

18:45:54.299 Running test: JIT/opt/Vectorization/UnrollEqualsStartsWIth/UnrollEqualsStartsWIth.dll
App Exit Code: 3
Expected: 100
Actual: 3
END EXECUTION - FAILED
FAILED
[XUnitLogChecker]: Item 'JIT.opt' did not finish running. Checking and fixing the log...
[XUnitLogChecker]: XUnit log file has been fixed!

211/292 tests run.
* 210 tests passed.
* 0 tests failed.
* 1 tests skipped.

[XUnitLogChecker]: Checking for dumps...
[XUnitLogChecker]: No crash dumps found. Continuing...
[XUnitLogChecker]: Finished!

@markples Another issue with merging?

cc @EgorBo

Author:	BruceForstall
Assignees:	-
Labels:	JitStress, area-CodeGen-coreclr, blocking-clean-ci-optional
Milestone:	8.0.0

[EgorBo]

Note: this test may be quite slow in stress modes, although, it used to work fine

[markples]

Do you think there is a JitStress/merged test group interaction here?

This test is interesting. It internally has a merged test group implementation and apparently has 127512 tests. They are executed via reflection, and a normal failure would cause one of the internal (sub-)batches to be terminated. A crash will take out the entire group. This infrastructure seems much heavier than the new wrapper code.

I think converting this to xunit-style tests would reduce the code, though a 100k+ test group would be a new stress to the system.

To be clear, I'm not suggesting any of that as a fix for the test failure - just something that I noticed while looking at the test.

[markples]

This has been inconsistent to repro across configurations. I have gotten it with -c Checked -lc Release and only in the merged group (and not in a "merged" group with just the one test. Visual Studio shuts down when this test is executed (and the report bug mechanism isn't properly searching for matching bugs for me). It isn't reproing under windbg.

There are a number of exception that are thrown and caught throughout the merged group - divide by zeros and access violations (for null). [edit - was incorrect - This test itself is as well (though I need to double check because I don't see null in the test list] Is there possibly an interaction between accessing null literals and jitstress? (or somehow a history of exceptions given the merged group interaction, but perhaps that is misleading somehow).

It seems like there is an actual problem even if merged groups are exposing it, though since it is jitstress it might be a jitstress issue and not a product one.

[markples]

The actual failure that the logs don't seem to capture (or maybe I've ended up in a different configuration?) is an assertion failure:

src/coreclr/vm/siginfo.cpp line 4928

void PromoteCarefully(promote_func   fn,
                      PTR_PTR_Object ppObj,
                      ScanContext*   sc,
                      uint32_t       flags /* = GC_CALL_INTERIOR*/ )
{
    LIMITED_METHOD_CONTRACT;

    //
    // Sanity check that the flags contain only these three values
    //
    assert((flags & ~(GC_CALL_INTERIOR|GC_CALL_PINNED)) == 0);

    //
    // Sanity check that GC_CALL_INTERIOR FLAG is set
    //
    assert(flags & GC_CALL_INTERIOR);

#if !defined(DACCESS_COMPILE)

    //
    // Sanity check the stack scan limit
    //
>>  assert(sc->stack_limit != 0);  <<

This suggests that the difficulty reproing it might have to do with GC timing. Does jitstress do anything odd with GC (triggering, reporting, etc.)? I.e., is it likely a jitstress or product issue?

I had previous seen a bit of a pattern where I can get the failure to happen the first time after building in src/tests but not again after that. It wasn't 100%, and it seems like confusing information since the test runs for a few seconds before failing (which makes some sort of cold start seem less likely).

It's certainly an interesting assertion to hit, though.

[BruceForstall]

Does jitstress do anything odd with GC (triggering, reporting, etc.)? I.e., is it likely a jitstress or product issue?

It appears to hit with multiple different JitStressRegs values. Maybe it does or would hit without JitStressRegs set if run enough?

It also appears to hit only with JitStress=2?

JitStress doesn't do anything specific related to GC: it doesn't trigger GC more, though might change between fully and partially interruptible. GC reporting changes because the generated code changes.

[markples]

Whether the "first time after building" observation is accurate or not, I was able to use it to get a case in windbg. Below is the stack trace. Note that, at first glance anyway, this doesn't look like a typical GC bug (misreporting, heap corruption, etc.) as the assertion is about the stack limit.

...
[0xf]    coreclr!PromoteCarefully+0x58   0xceff140   0x6124d51b   
[0x10]   coreclr!GcEnumObject+0x4b   0xceff15c   0x61067cae   
[0x11]   coreclr!EECodeManager::EnumGcRefs+0xe3e   0xceff178   0x6124d782   
[0x12]   coreclr!GcStackCrawlCallBack+0x152   0xceff5dc   0x611752fa   
[0x13]   coreclr!Thread::MakeStackwalkerCallback+0x48   0xceff634   0x611769d4   
[0x14]   coreclr!Thread::StackWalkFramesEx+0x186   0xceff650   0x611767ce   
[0x15]   coreclr!Thread::StackWalkFrames+0x159   0xceff928   0x6124cc04   
[0x16]   coreclr!ScanStackRoots+0x196   0xceffc60   0x6124addf   
[0x17]   coreclr!GCToEEInterface::GcScanRoots+0xf1   0xceffd74   0x6148c192   
[0x18]   coreclr!WKS::gc_heap::background_mark_phase+0x406   0xceffd98   0x61495ffe   
[0x19]   coreclr!WKS::gc_heap::gc1+0x13b   0xceffe00   0x6148e51d   
[0x1a]   coreclr!WKS::gc_heap::bgc_thread_function+0xcc   0xceffe24   0x6148e6c7   
[0x1b]   coreclr!WKS::gc_heap::bgc_thread_stub+0x27   0xceffe44   0x6124976e   
[0x1c]   coreclr!<lambda_6e1c80cead0a95b6f179a4ba7ad5e186>::operator()+0x84   0xceffe48   0x75a47d59   
[0x1d]   KERNEL32!BaseThreadInitThunk+0x19   0xceffe68   0x77d0b74b   
[0x1e]   ntdll!__RtlUserThreadStart+0x2b   0xceffe78   0x77d0b6cf   
[0x1f]   ntdll!_RtlUserThreadStart+0x1b   0xceffed0   0x0   

[BruceForstall]

Maybe @dotnet/gc or @janvorli have insight?

[mangod9]

@markples do you have the dumps available? @cshung is this related to any of your recent changes?

[janvorli]

@markples if you can share the dump and the contents of the artifacts\tests\coreclr\Windows.x64.XXXXX\Tests\Core_Root, I can take a look.

[markples]

Thanks @janvorli. I've copied a .dump /m, .dump /mf, and the contents of Windows.x86.checked\Tests\Core_Root to https://microsoft-my.sharepoint.com/:f:/p/markples/EmAjXtmylUxMoQPjBpFC9ucBd5mGrD0IKPPopBCkJr0H4g?e=7z4efq. This should have MSFT-organization access.

A few key points from the discussion above:

• Repro is so far x86 only
• Repro is running under a jit stress mode
• Repro is very unreliable, though I have seen a strong correlation between hitting one and the first execution after building in src\tests