Repository navigation
Test failure: JIT\\Regression\\JitBlue\\GitHub_27924\\GitHub_27924\\GitHub_27924.cmd #36681
Description
failed in job: runtime-coreclr jitstress 20200517.2
Error message
Assert failure(PID 5488 [0x00001570], Thread: 11524 [0x2d04]): _safePointDecoder.IsSafePoint(curOffs)
<no module>! <no symbol> + 0x0 (0x00000000)
File: F:\workspace\_work\1\s\src\coreclr\src\vm\eetwain.cpp Line: 5044
Image: D:\h\w\AAF5093E\p\CoreRun.exe
Return code: 1
Raw output file: D:\h\w\AAF5093E\w\B29D099C\e\JIT\Regression\Reports\JIT.Regression\JitBlue\GitHub_27924\GitHub_27924\GitHub_27924.output.txt
Raw output:
BEGIN EXECUTION
"D:\h\w\AAF5093E\p\corerun.exe" GitHub_27924.dll
Expected: 100
Actual: -1073740286
END EXECUTION - FAILED
FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=D:\h\w\AAF5093E\p
> D:\h\w\AAF5093E\w\B29D099C\e\JIT\Regression\JitBlue\GitHub_27924\GitHub_27924\GitHub_27924.cmd
Expected: True
Actual: False
Stack trace
at JIT_Regression._JitBlue_GitHub_27924_GitHub_27924_GitHub_27924_._JitBlue_GitHub_27924_GitHub_27924_GitHub_27924_cmd() in F:\workspace\_work\1\s\artifacts\tests\coreclr\Windows_NT.arm.Checked\TestWrappers\JIT.Regression\JIT.Regression.XUnitWrapper.cs:line 122360
category:correctness
theme:gc-stress
skill-level:expert
cost:large
Activity
safern commentedon May 26, 2020
@BruceForstall any update on this?
This failed again on: https://helix.dot.net/api/2019-06-17/jobs/eb11af78-3bd5-4fce-ad89-49b91832128d/workitems/JIT.Regression/console
https://dnceng.visualstudio.com/public/_build/results?buildId=659717&view=logs&j=6ffa34aa-4e0e-5e33-51b1-9621a575e196&t=2fdabd0b-7202-58e4-755d-1556a81de2e1&l=38
BruceForstall commentedon May 26, 2020
@safern I haven't had a chance to look at this yet. Hopefully this week.
v-haren commentedon Jun 12, 2020
failed again in job: runtime-coreclr jitstress 20200610.1
failed test: JIT\Regression\JitBlue\GitHub_27924\GitHub_27924\GitHub_27924.cmd
Error message
BruceForstall commentedon Jun 12, 2020
Failures are in
CoreCLR Windows_NT arm Checked zapdisable @ Windows.10.Arm64v8.OpenBruceForstall commentedon Jun 13, 2020
(Note: Windows arm issue)
Even though this configuration sets:
the test also sets
(it's the only one in the coreclr test tree to do so, and it's a Pri-0 test, so it probably gets more GCStress runs by far than any other test.)
I couldn't repro it initially, but when I tweaked some of the loops I was able to repro about every 10+ runs, and caught it in the debugger.
The assert is in GCstress code in
EECodeManager::EnumGcRefs()that asserts that if the current IP is non-interruptible, then it is a safe point offset after a call, specifically:There are many threads. The thread being walked that causes the assert is:
in this case, the first "real" frame is
System_Private_CoreLib!System.Threading.FastRandom.Next(<Win32 error 0n318>)+0x74, which looks like:So, we're actually AT the last call instruction, in a non-interruptible region, not after the call instruction.
So, how do we get here? Is there some kind of initial stack walk setup that is getting confused on this call?
What's also interesting is that while we are running with
COMPlus_GCStress=C, it looks like we are doing gcstress due to an allocation, not a stressed JIT/R2R instruction, based on the thread that seems to be the one to be triggering the GC[edit: it looks like when concurrent GC is "forced" (I can't tell why it would be considered "forced" in this case),
EEConfig::sync()adds in GCStress 3].Other information at this point:
@janvorli @AndyAyersMS Any suggestions for what to look at next?
BruceForstall commentedon Jun 13, 2020
There's something strange about the EE suspension. Through multiple GCs, there are 3 threads waiting for
System.Threading.FastRandom.Next(Int32)to JIT; GC stack walks show ExplicitFrame in thePrestubMethodFrame. Then, in the next, failing case, all these three are sitting on the same instruction insideNext(), which is on a call instruction and not a GC safe point.Two of these continue and return to the caller, a safe point, before suspension ends. The third, TID 28d0, does not, so we end up suspended but not at a safe point.
StressLog_top.txt
janvorli commentedon Jun 15, 2020
I can see that GC stress mode C injects the special invalid instructions at call sites too, but it should be detected as a special case (the instruction is different for call sites).
Can you see any local variable values at the following frame? I would like to see if it was correctly detected as a call site (
atCallbeing true) - it seems it would not be the case. If we cannot get any details from the dump, we might need to add some stresslog logging here to give us more details, or alternatively try to repro the problem in debug buildI was wondering if by some mistake, the GCCoverageInfo::SprinkleBreakpoints doesn't put in an incorrect invalid instruction that would indicate it is a safe point instead of a call.
Looking at the code in replaceSafePointInstructionWithGcStressInstr that gets called from the GCCoverageInfo::SprinkleBreakpoints, it seems it should work correctly for our call instruction (instr code 0x4798):
runtime/src/coreclr/src/vm/gccover.cpp
Lines 814 to 828 in 2799404
Although there seems to actually be a bug in this code. When it detects a call through immediate, it sets instructionIsACallThroughRegister instead of instructionIsACallThroughImmediate. But this should not cause the issue we are seeing.
We also really need to do the 2nd check (for calls through immediate) only if the first check for calls through register fails, but that's again not a bug.
14 remaining items
AndyAyersMS commentedon Aug 27, 2020
No luck after several thousand iterations.
@BruceForstall you mentioned altering the test to make the failures repro more readily?
BruceForstall commentedon Aug 27, 2020
I simply upped the loops, from
1000000to100_000_000, and10000to1_000_000. I presume you're already running theCOMPlus_GCStress=C.I'm also running with:
which might all be required.
BruceForstall commentedon Aug 28, 2020
I found a race condition in the GCStress infrastructure which I believe causes this problem. The details are related to what Jan suggested above about a problem with
atCall, as follows:Consider the case of a partially interruptible function where we've replaced each call site with
INTERRUPT_INSTR_CALLorINTERRUPT_INSTR_CALL_32. Even though the call site itself isn't a safe point, we put a GCStress instruction there so we can capture the call target at GC time, then set a specific GCStress instruction for the next instruction that will indicate how to GC protect any GC refs that are returned from the call.Multiple threads can enter
DoGcStressat the same time. They all get just past the race checkif (!IsGcCoverageInterruptInstruction(instrPtr)) return;. One goes ahead, and reads the instruction code for the address at which we're doing a GCStress. We setatCallto true if this matches one of our known GCStress instructions for partially-interruptible call sites. Later, ifatCallis true, we write the original call instruction back to the code stream, write the distinguished next instruction GCStress instruction, and continue. If the other threads then read at the instruction address, they might read the actual call opcode, not the distinguished GCStress breakpoint instruction code. Then, they will setatCallto false. This will indicate that we are in a fully-interruptible location, or that no special call-site behavior is required. We go on, force a GC, and eventually get to this assert inEECodeManager::EnumGcRefsthat we are at a GC safe point.It seems like this should be an all-platform issue, so I'm not sure why we only see it on Windows arm32 (except that it's very rare, and this particular test that exposes it (rarely) is run with GCStress much more frequently on Windows than Linux, and arm32 is probably a lot slower and potentially exposes the race more as a result).
It seems like the solution should be to simply move the
if (!IsGcCoverageInterruptInstruction(instrPtr))check down below the read of*instrPtrto setatCall.AndyAyersMS commentedon Aug 28, 2020
I couldn't repro with upped loop counts and also with some sideloaded stress.
Note for arm32 we make multiple reads of instrPtr so perhaps the race window is much larger? It also means the fix is a perhaps bit more complex; we need to be careful to make just one read, then (perhaps?) use interlocked ops to try and update, so there's just one "winner".
BruceForstall commentedon Aug 28, 2020
The reason we read multiple times is to determine if we've got a 2-byte or a 4-byte instruction encoding, using
GetARMInstructionLength. I don't think there is any other case of reading more than once. However, I don't think that matters because we always replace a 2-byte instruction with a 2-byte instruction and a 4-byte instruction with a 4-byte instruction, so the result of callingGetARMInstructionLengthshouldn't change depending on whether we're reading the original or a new instruction. Perhaps there is some effect on the race window simply by reading twice.BruceForstall commentedon Aug 28, 2020
With my fix of moving the
(!IsGcCoverageInterruptInstruction(instrPtr))check, I've run >500 iterations without a failure. Before, it failed consistently in the first 10 or 20 iterations.AndyAyersMS commentedon Aug 28, 2020
I suppose we won't ever see torn reads so you are probably right about re-reads being fairly harmless.
That's great news. Thanks for digging into this one.
BruceForstall commentedon Aug 28, 2020
There definitely are assumptions in the GCStress code about not seeing torn reads, and that any
*instrPtrread will beatomic. I'm not sure how valid these assumptions are, and it does seem that switching to use interlocked operations might be safer, although perhaps with some significant performance penalty.Fix a race condition in GCStress
BruceForstall commentedon Aug 28, 2020
Since this is GCStress only, moving to 6.0.
Fix a race condition in GCStress (#41540)