Menu
I've been chasing down the cause of an intermittent crash in one of our .NET services due to an internal error in the .NET Runtime (exit code 0x80131506). The service in question doesn't perform any of the kinds of operation that are usually to blame for such errors (unsafe code, PInvoke, etc.). I've tried disabling concurrent GC as described in KB2679415, as well as switching to server GC, but the intermittent crashes persist. The issue manifests on .NET 4.7.2 and earlier versions, when compiled in debug mode.
The service makes extensive use of an old version of NHibernate (2.0.1), and when I've examined crash dumps in the debugger, there is always NHibernate code in the callstack when the error occurs, though NHibernate itself is all managed code, so should not be capable of causing this kind of crash.
I have managed to reproduce the crash under a debugger and with the GC Stress Log and Heap Verification enabled, and whilst it seems to point to an issue within the JIT/GC, I'm not sure I'm interpreting the output correctly.
Looking at the thread on which the crash occurs, on this occasion it's occurring at clr!JIT_Stelem_Ref:
clr!JIT_Stelem_Ref+0x18: cmp r9,qword ptr [r8] ds:aaaaaaaa`aaaaaaaa=????????????????
In this case the string of 0xaas appears to be the result of having HeapVerify enabled, which causes the GC fill collected memory regions, presumably for easier identification, and suggests that somehow we still have a reference to the old location of a collected/relocated object.
Tracking back in the stack, there are plenty of 0xaaaaaaaaaaaaaaaa entries, however these cease appearing at the method that was at the top of the call stack when the most recent GC occurred, which in this case was NHibernate.Loader.Loader.GetRow() according to the GC stress log for the most recent GC on this thread:
(Note: I've reversed the order of the logged lines from SOS' !dumplog output for easier reading):
2404 12445.672380360 : `GC`GCROOTS` Starting scan of Thread 000000001EF4DED0 ID = 20 {
2404 12445.672380963 : `GCROOTS` Scanning ExplicitFrame 000000001E6ED3B8 AssocMethod = 0000000000000000 frameVTable = 000007FEF365B640 (clr!RedirectedThreadFrame::`vftable')
2404 12445.672386397 : `GCROOTS` Scanning Frameless method 000007FE93F43460 (NHibernate.Loader.Loader.GetRow(System.Data.IDataReader, NHibernate.Persister.Entity.ILoadable[], NHibernate.Engine.EntityKey[], System.Object, NHibernate.Engine.EntityKey, NHibernate.LockMode[], System.Collections.IList, NHibernate.Engine.ISessionImplementor)) ControlPC = 000007FE945E3095
2404 12445.672388208 : `GC`GCROOTS` GC Root 000000001E6ED4C0 RELOCATED 000000003B1A7708 -> 000000003AC89F08 MT = 000007FE93DDF5C8 (...)
2404 12445.672388510 : `GC`GCROOTS` GC Root 000000001E6ED4D8 RELOCATED 000000003B1A73A0 -> 000000003AC89D00 MT = 000007FEF1FD6EA8 (System.Object[])
2404 12445.672388510 : `GC`GCROOTS` GC Root 000000001E6ED4E8 RELOCATED 000000003B1A7358 -> 000000003AC89CB8 MT = 000007FE9491D7C8 (NHibernate.Engine.EntityKey)
2404 12445.672388510 : `GC`GCROOTS` GC Root 000000001E6ED4F8 RELOCATED 000000003B1A73A0 -> 000000003AC89D00 MT = 000007FEF1FD6EA8 (System.Object[])
The stack area for this method is as follows:
00000000`1e6ed470 000000003b1a7358 ✕
00000000`1e6ed478 000000000291e3d0
00000000`1e6ed480 0000000000000000
00000000`1e6ed488 0000000000000000
00000000`1e6ed490 000000000662a900
00000000`1e6ed498 0000000006523c80
00000000`1e6ed4a0 0000000000000000
00000000`1e6ed4a8 0000000000000000
00000000`1e6ed4b0 0000000000000000
00000000`1e6ed4b8 0000000000000000
00000000`1e6ed4c0 000000003ac89f08 ✔
00000000`1e6ed4c8 0000000000000000
00000000`1e6ed4d0 0000000006524248
00000000`1e6ed4d8 000000003ac89d00 ✔
00000000`1e6ed4e0 0000000000000000
00000000`1e6ed4e8 000000003ac89cb8 ✔
00000000`1e6ed4f0 0000000000000000
00000000`1e6ed4f8 000000003ac89d00 ✔
00000000`1e6ed500 0000000100000000
00000000`1e6ed508 0000000c0000000b
00000000`1e6ed510 0000000006621660
00000000`1e6ed518 000000001e6ed690
00000000`1e6ed520 000000001e6ed6a0
I have indicated the 4 entries mentioned in the GC stress log as relocated, which have been correctly updated with their new addresses, however the first stack entry (000000003b1a7358 - an NHibernate.Engine.EntityKey), whilst it is one of the relocated objects has not been updated with the new address. This would of course be completely normal if this was no longer going to be used, however it is in fact about to be passed as a parameter to a call to NHibernate.Loader.Loader.InstanceNotYetLoaded().
InstanceNotYetLoaded() takes 9 parameters (plus this), and I have marked where each of these is loaded into the stack/register on the following assembly listing. I have also included the relevant output from SOS' !gcinfo as it relates to each of the parameters on the stack:
Param Address Instruction GC Info
000007fe`945e3071 mov r9,qword ptr [rbp-38h]
P4> 000007fe`945e3075 mov qword ptr [rsp+20h],r9
000007fe`945e307a mov r9d,dword ptr [rbp-18h] +sp+20
000007fe`945e307e mov rcx,qword ptr [rbp+40h]
000007fe`945e3082 cmp r9,qword ptr [rcx+8]
000007fe`945e3086 jb 000007fe`945e308d
000007fe`945e3088 call clr!JIT_RngChkFail
000007fe`945e308d lea rcx,[rcx+r9*8+10h] -sp+20
000007fe`945e3092 mov r9,qword ptr [rcx]
-- GC Occurred Here --
P5> 000007fe`945e3095 mov qword ptr [rsp+28h],r9
000007fe`945e309a mov r9,qword ptr [rbp+38h] +sp+28
P6> 000007fe`945e309e mov qword ptr [rsp+30h],r9
000007fe`945e30a3 mov r9,qword ptr [rbp+30h] +sp+30
P7> 000007fe`945e30a7 mov qword ptr [rsp+38h],r9
000007fe`945e30ac mov r9,qword ptr [rbp+48h] +sp+38
P8> 000007fe`945e30b0 mov qword ptr [rsp+40h],r9
000007fe`945e30b5 mov r9,qword ptr [rbp+50h] +sp+40
P9> 000007fe`945e30b9 mov qword ptr [rsp+48h],r9
000007fe`945e30be mov r9d,dword ptr [rbp-18h] +sp+48
000007fe`945e30c2 mov rcx,qword ptr [rbp+20h]
000007fe`945e30c6 cmp r9,qword ptr [rcx+8]
000007fe`945e30ca jb 000007fe`945e30d1
000007fe`945e30cc call clr!JIT_RngChkFail
000007fe`945e30d1 lea rcx,[rcx+r9*8+10h] -sp+48 -sp+40 -sp+38 -sp+30 -sp+28
P3> 000007fe`945e30d6 mov r9,qword ptr [rcx]
this> 000007fe`945e30d9 mov rcx,qword ptr [rbp+10h]
P1> 000007fe`945e30dd mov rdx,qword ptr [rbp+18h]
P2> 000007fe`945e30e1 mov r8d,dword ptr [rbp-18h]
000007fe`945e30e5 call InstanceNotYetLoaded(...)
The GC just prior to the crash occurred at 000007fe945e3095, which is after parameter 4 is loaded onto the stack (at 000007fe945e3075), but also after this stack entry has become dead (at 000007fe945e308d) according to the GC Info, which would explain why the GC relocate phase didn't update this reference.
It also looks like the GC Info for parameters 5-9 is also incorrectly marking them as dead too early, and perhaps tellingly in both cases they are being marked dead immediately after what looks like an array index range check.
This to me looks like a JIT bug with the lifetimes of these stack parameters being incorrectly tracked. Is this analysis correct, if so where best to report if. If it's not a JIT bug, what am I missing that could explain these unexpected crashes on purely managed code?
I believe the following snippet will reproduce the issue, at least as far as generating the bad GC info in debug mode.
public void Repro(int p1, object p2, object p3, object p4, object[] p5)
{
// Incorrect GC Info generated for this call
ReproHelper(p1, p2, p3, p4, p5[p1]);
}
public void ReproHelper(int p1, object p2, object p3, object p4, object p5)
{
Console.WriteLine(p1);
Console.WriteLine(p2);
Console.WriteLine(p3);
Console.WriteLine(p4);
Console.WriteLine(p5);
}
In essence, there must be a method call to a method that:
When these criteria are met, the 4th parameter is loaded onto the stack for the call, and the stack entry is correctly marked as containing a reference. However in determining the value for parameter 5, an array index range check is made, and after this occurs the stack entry for parameter 4 is marked as dead.
If a GC occurs after the range check but before the actual call takes place, and the GC results in the object that was being passed as parameter 4 being relocated, when the method resumes, the call will pass the old (invalid) address to parameter 4, rather than the new one.
527
While it is not an answer to the problem, I treat it as such because I confirm it is a bug and should be fixed by the .NET team.
When running your snippet on .NET Framework 4.7.1 (clrjit.dll version 4.7.2xxx), proper GCInfo was generated (and +sp+20 is in fact written to only just before ReproHelper call):
00007ffb`99450630 55 push rbp
00007ffb`99450631 4883ec40 sub rsp,40h
00000003 is a safepoint:
00007ffb`99450635 488d6c2440 lea rbp,[rsp+40h]
00007ffb`9945063a 33c0 xor eax,eax
00007ffb`9945063c 488945f8 mov qword ptr [rbp-8],rax
00007ffb`99450640 48894d10 mov qword ptr [rbp+10h],rcx
00007ffb`99450644 895518 mov dword ptr [rbp+18h],edx
00007ffb`99450647 4c894520 mov qword ptr [rbp+20h],r8
00007ffb`9945064b 4c894d28 mov qword ptr [rbp+28h],r9
interruptible
+rbp+28 +rbp+20 +rbp+10 +rbp-8
00007ffb`9945064f 833d3a3fefff00 cmp dword ptr [00007ffb`99344590],0
00007ffb`99450656 7405 je 00007ffb`9945065d
00007ffb`99450658 e863eaab5f call clr!JIT_DbgIsJustMyCode (00007ffb`f8f0f0c0)
00007ffb`9945065d 90 nop
00007ffb`9945065e 8b5518 mov edx,dword ptr [rbp+18h]
00007ffb`99450661 4c8b4538 mov r8,qword ptr [rbp+38h]
+r8
00007ffb`99450665 413b5008 cmp edx,dword ptr [r8+8]
00007ffb`99450669 7205 jb 00007ffb`99450670
-rbp-8
00007ffb`9945066b e8f015ac5f call clr!JIT_RngChkFail (00007ffb`f8f11c60)
-r8
00007ffb`99450670 488b5538 mov rdx,qword ptr [rbp+38h]
+rdx
00007ffb`99450674 448b4518 mov r8d,dword ptr [rbp+18h]
00007ffb`99450678 4d63c0 movsxd r8,r8d
00007ffb`9945067b 4a8b54c210 mov rdx,qword ptr [rdx+r8*8+10h]
00007ffb`99450680 488955f8 mov qword ptr [rbp-8],rdx
+rbp-8
00007ffb`99450684 488b55f8 mov rdx,qword ptr [rbp-8]
00007ffb`99450688 4889542428 mov qword ptr [rsp+28h],rdx
+sp+28
00007ffb`9945068d 8b5518 mov edx,dword ptr [rbp+18h]
-rdx
00007ffb`99450690 4c8b4520 mov r8,qword ptr [rbp+20h]
+r8
00007ffb`99450694 4c8b4d28 mov r9,qword ptr [rbp+28h]
+r9
00007ffb`99450698 488b4d30 mov rcx,qword ptr [rbp+30h]
+rcx
00007ffb`9945069c 48894c2420 mov qword ptr [rsp+20h],rcx
+sp+20
00007ffb`994506a1 488b4d10 mov rcx,qword ptr [rbp+10h]
-rbp-8
But after upgrading to .NET Framework 4.7.2 (clrjit.dll version 4.7.3062), it is no longer correct (+sp+20 is written to before array index range check, properly set but out of a sudden unset afterwards, while still used in the ReproHelper call):
00007ffe`62290630 55 push rbp
00007ffe`62290631 4883ec30 sub rsp,30h
00007ffe`62290635 488d6c2430 lea rbp,[rsp+30h]
00000007 is a safepoint:
00007ffe`6229063a 48894d10 mov qword ptr [rbp+10h],rcx
00007ffe`6229063e 895518 mov dword ptr [rbp+18h],edx
00007ffe`62290641 4c894520 mov qword ptr [rbp+20h],r8
00007ffe`62290645 4c894d28 mov qword ptr [rbp+28h],r9
interruptible
+rbp+28 +rbp+20 +rbp+10
00007ffe`62290649 833d483fefff00 cmp dword ptr [00007ffe`62184598],0
00007ffe`62290650 7405 je 00007ffe`62290657
00007ffe`62290652 e869f7aa5f call clr!TranslateSecurityAttributes+0x857b0 (00007ffe`c1d3fdc0) (JitHelp: CORINFO_HELP_DBG_IS_JUST_MY_CODE)
00007ffe`62290657 90 nop
00007ffe`62290658 488b4d30 mov rcx,qword ptr [rbp+30h]
+rcx
00007ffe`6229065c 48894c2420 mov qword ptr [rsp+20h],rcx
+sp+20
00007ffe`62290661 8b4d18 mov ecx,dword ptr [rbp+18h]
-rcx
00007ffe`62290664 488b5538 mov rdx,qword ptr [rbp+38h]
+rdx
00007ffe`62290668 483b4a08 cmp rcx,qword ptr [rdx+8]
00007ffe`6229066c 7205 jb 00007ffe`62290673
00007ffe`6229066e e8ed22ab5f call clr!TranslateSecurityAttributes+0x88350 (00007ffe`c1d42960) (JitHelp: CORINFO_HELP_RNGCHKFAIL)
-sp+20
00007ffe`62290673 488d54ca10 lea rdx,[rdx+rcx*8+10h]
-rdx +rdx(interior)
00007ffe`62290678 488b0a mov rcx,qword ptr [rdx]
+rcx
00007ffe`6229067b 48894c2428 mov qword ptr [rsp+28h],rcx
+sp+28
00007ffe`62290680 488b4d10 mov rcx,qword ptr [rbp+10h]
00007ffe`62290684 8b5518 mov edx,dword ptr [rbp+18h]
-rdx(interior)
00007ffe`62290687 4c8b4520 mov r8,qword ptr [rbp+20h]
+r8
00007ffe`6229068b 4c8b4d28 mov r9,qword ptr [rbp+28h]
+r9
00007ffe`6229068f e804faffff call 00007ffe`62290098 (GCInfoBug.Bug.ReproHelper(Int32, System.Object, System.Object, System.Object, System.Object), mdToken: 0000000006000004)
-sp+28 -r9 -r8 -rcx
00007ffe`62290694 90 nop
00007ffe`62290695 90 nop
not interruptible
-rbp+28 -rbp+20 -rbp+10
00007ffe`62290696 488d6500 lea rsp,[rbp]
00007ffe`6229069a 5d pop rbp
00007ffe`6229069b c3 ret
Thanks you for providing such a detailed investigation along with this bug report.
Microsoft will be fixing this issue in 4.7.2 an upcoming servicing release.
30
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With
