Simple/Threading test is crashing intermittently on Linux/OSX Release

[jkotas]

Repro:

1. Build release on Linux or OSX
2. Run Simple/Threading test in a loop

Result: Intermittent crash with this callstack:

  * frame #0: 0x000000010003c450 Threading`WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int) + 16
    frame #1: 0x000000010000dd44 Threading`EnumGcRefsCallback(void*, void**, unsigned int) + 36
    frame #2: 0x000000010009c2ae Threading`GcInfoDecoder::EnumerateLiveSlots(REGDISPLAY*, bool, unsigned int, void (*)(void*, void**, unsigned int), void*) + 5230
    frame #3: 0x000000010009df78 Threading`UnixNativeCodeManager::EnumGcRefs(MethodInfo*, void*, REGDISPLAY*, GCEnumContext*) + 136
    frame #4: 0x000000010000dd0d Threading`RedhawkGCInterface::EnumGcRefs(ICodeManager*, MethodInfo*, void*, REGDISPLAY*, void*, void*) + 45
    frame #5: 0x000000010001bede Threading`Thread::GcScanRootsWorker(void*, void*, StackFrameIterator&) + 350
    frame #6: 0x000000010001bd65 Threading`Thread::GcScanRoots(void*, void*) + 85
    frame #7: 0x000000010000eaf9 Threading`GCToEEInterface::GcScanRoots(void (*)(Object**, ScanContext*, unsigned int), int, int, ScanContext*) + 313
    frame #8: 0x0000000100030f74 Threading`WKS::gc_heap::mark_phase(int, unsigned int) + 420
    frame #9: 0x000000010002e850 Threading`WKS::gc_heap::gc1() + 448

[jkotas]

The thread that we are stackwalking is stopped at:

* frame #0: 0x00007fffb445cbf2 libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007fffb45487fa libsystem_pthread.dylib`_pthread_cond_wait + 712
    frame #2: 0x0000000100097e0b Threading`UnixEvent::Wait(unsigned int) + 347
    frame #3: 0x000000010000bf6a Threading`CLREventStatic::Wait(unsigned int, bool, bool) + 122
    frame #4: 0x000000010001c37a Threading`RhpWaitForGC2 + 90
    frame #5: 0x0000000100160668 Threading`S_P_CoreLib_System_Threading_ClrThreadPool_WaitThread__WaitThreadStart + 64
    frame #6: 0x00000001001311d8 Threading`S_P_CoreLib_Internal_Runtime_Augments_RuntimeThread__StartThread + 188
    frame #7: 0x0000000100124f05 Threading`S_P_CoreLib_Internal_Runtime_Augments_RuntimeThread__ThreadEntryPoint + 25
    frame #8: 0x00007fffb454793b libsystem_pthread.dylib`_pthread_body + 180
    frame #9: 0x00007fffb4547887 libsystem_pthread.dylib`_pthread_start + 286

Looks like the GCInfo around CoreLibNative_GetTickCount64 PInvoke is not right, or is not interpreted correctly.

[jkotas]

cc @adityamandaleeka

[jkotas]

It does not repro with debug build.

It does repro in release build with optimizations disabled and debug info enabled for the unmanaged runtime here (useful for debugging): https://github.com/dotnet/corert/blob/master/src/Native/CMakeLists.txt#L229 .

[adityamandaleeka]

Thanks @jkotas. I'm trying to repro it now. Roughly how frequently does it repro for you?

[jkotas]

Repros reliably in <10 tries (on Macbook).

[jkotas]

BTW: The crash looks exactly same as #4214 . It looks like that the fix was incomplete.

[adityamandaleeka]

Thanks, I am able to reproduce this now.

[sergiy-k]

cc @sandreenko

[adityamandaleeka]

Yea, this is the same issue as #4214. The thread we're scanning is here:

    0x1001e5af8 <+260>: movl   $0xffffffff, %esi         ; imm = 0xFFFFFFFF 
    0x1001e5afd <+265>: jmp    0x1001e5b39               ; <+325>
    0x1001e5aff <+267>: movq   %r15, -0x48(%rbp)
    0x1001e5b03 <+271>: leaq   -0x78(%rbp), %rdi
    0x1001e5b07 <+275>: callq  0x1001be7cc               ; RhpPInvoke
    0x1001e5b0c <+280>: callq  0x1001c0010               ; ::CoreLibNative_GetTickCount64() at pal_time.cpp:107 <---------------- note: this is where the transition frame's RIP is
    0x1001e5b11 <+285>: movq   %rax, %rbx
    0x1001e5b14 <+288>: leaq   -0x78(%rbp), %rdi
    0x1001e5b18 <+292>: callq  0x1001be810               ; RhpPInvokeReturn
->  0x1001e5b1d <+297>: movq   %rbx, %rdi
    0x1001e5b20 <+300>: subl   -0x30(%rbp), %edi
    0x1001e5b23 <+303>: cmpl   -0x2c(%rbp), %edi
    0x1001e5b26 <+306>: jle    0x1001e5b30               ; <+316>
    0x1001e5b28 <+308>: xorl   %esi, %esi

and the register we're trying to report as live is R15 (callee-saved), which contradicts the comment on RhpPInvoke where we say 'the codegenerator must ensure that there are no live GC references in callee saved registers.'

I'm not familiar with the LSRA code @sandreenko fixed, so I don't know yet why that fix isn't sufficient.

[sandreenko]

I will take a look.

[adityamandaleeka]

@sandreenko I might have a clue about what's going on. Here's an extended snippet of the disassembly:

    0x1001e5afd <+265>: jmp    0x1001e5b39               ; <+325>
    0x1001e5aff <+267>: movq   %r15, -0x48(%rbp)
    0x1001e5b03 <+271>: leaq   -0x78(%rbp), %rdi
    0x1001e5b07 <+275>: callq  0x1001be7cc               ; RhpPInvoke
    0x1001e5b0c <+280>: callq  0x1001c0010               ; ::CoreLibNative_GetTickCount64() at pal_time.cpp:107
    0x1001e5b11 <+285>: movq   %rax, %rbx
    0x1001e5b14 <+288>: leaq   -0x78(%rbp), %rdi
    0x1001e5b18 <+292>: callq  0x1001be810               ; RhpPInvokeReturn
->  0x1001e5b1d <+297>: movq   %rbx, %rdi
    0x1001e5b20 <+300>: subl   -0x30(%rbp), %edi
    0x1001e5b23 <+303>: cmpl   -0x2c(%rbp), %edi
    0x1001e5b26 <+306>: jle    0x1001e5b30               ; <+316>
    0x1001e5b28 <+308>: xorl   %esi, %esi
    0x1001e5b2a <+310>: movq   -0x48(%rbp), %r15
    0x1001e5b2e <+314>: jmp    0x1001e5b39               ; <+325>

Based on the GC liveness info, we're dropping R15 at offset 280 and then making it live again at 314.

However, our transition frame that we push prior to the PInvoke has the RIP at offset 275, which explains why we think R15 is still live. Oops, I misread this part. The RIP in the transition frame is actually at offset 280.

[dlewis-arcontech]

Think I've found a similar issue, running code that uses several threads where the number of threads are configurable (lowering the number of thread reduces the chance of this issue happening). The code works fine when running just as JIT code but not as AOT compiled to native code. Code running on Ubuntu 14.04.5 LTS. Call stack as follows:

• thread CoreLib doesn't implement Environment.GetEnvironmentVariable and friends #6: tid = 44826, 0x0000000000417bbc ConsoleApp1`EEType::get_BaseSize(this=0x0000000000000000) + 12 at eetype.h:365, name = 'ConsoleApp1', stop reason = signal SIGSEGV: invalid address (fault address: 0x4)
  • frame #0: 0x0000000000417bbc ConsoleApp1EEType::get_BaseSize(this=0x0000000000000000) + 12 at eetype.h:365 frame #1: 0x00000000004edfd5 ConsoleApp1MethodTable::GetBaseSize(this=0x0000000000000000) + 21 at gcenv.h:91
    frame Add basic build scripts #2: 0x0000000000494328 ConsoleApp1WKS::gc_heap::mark_object_simple1(unsigned char*, unsigned char*) [inlined] WKS::my_get_size(ob=0x00007fffdfd4b568) + 25 at gc.cpp:8897 frame #3: 0x000000000049430f ConsoleApp1WKS::gc_heap::mark_object_simple1(oo="\x01��", start="\xb0\x87\xaa���") + 6927 at gc.cpp:17730
    frame Improve .gitignore #4: 0x00000000004953bb ConsoleApp1WKS::gc_heap::mark_object_simple(po=0x00007fffccb1b020) + 1883 at gc.cpp:18174 frame #5: 0x000000000049e281 ConsoleApp1WKS::GCHeap::Promote(ppObject=0x00007fffccb1cc28, sc=0x00007fffccb1bfc8, flags=0) + 1137 at gc.cpp:33817
    frame CoreLib doesn't implement Environment.GetEnvironmentVariable and friends #6: 0x0000000000419313 ConsoleApp1GcEnumObject(ppObj=0x00007fffccb1cc28, flags=0, fnGcEnumRef=(ConsoleApp1WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int) at gc.cpp:33749), pSc=0x00007fffccb1bfc8)(Object**, ScanContext*, unsigned int), ScanContext*) + 131 at gcrhscan.cpp:150
    frame Add type system source files #7: 0x0000000000415c54 ConsoleApp1EnumGcRefsCallback(hCallback=0x00007fffccb1b9a0, pObject=0x00007fffccb1cc28, flags=0) + 68 at gcrhenv.cpp:508 frame #8: 0x00000000005db4dc ConsoleApp1GcInfoDecoder::ReportStackSlotToGC(this=0x00007fffccb1b8c8, spOffset=-72, spBase=GC_FRAMEREG_REL, gcFlags=0, pRD=0x00007fffccb1bae0, flags=0, pCallBack=(ConsoleApp1EnumGcRefsCallback(void*, void**, unsigned int) at gcrhenv.cpp:505), hCallBack=0x00007fffccb1b9a0)(void*, void**, unsigned int), void*) + 156 at gcinfodecoder.cpp:1827 frame #9: 0x00000000005dcd29 ConsoleApp1GcInfoDecoder::ReportSlotToGC(this=0x00007fffccb1b8c8, slotDecoder=0x00007fffccb1b7c8, slotIndex=15, pRD=0x00007fffccb1bae0, reportScratchSlots=true, inputFlags=0, pCallBack=(ConsoleApp1EnumGcRefsCallback(void*, void**, unsigned int) at gcrhenv.cpp:505), hCallBack=0x00007fffccb1b9a0)(void*, void**, unsigned int), void*) + 377 at gcinfodecoder.h:688 frame #10: 0x00000000005da12a ConsoleApp1GcInfoDecoder::ReportUntrackedSlots(this=0x00007fffccb1b8c8, slotDecoder=0x00007fffccb1b7c8, pRD=0x00007fffccb1bae0, inputFlags=0, pCallBack=(ConsoleApp1EnumGcRefsCallback(void*, void**, unsigned int) at gcrhenv.cpp:505), hCallBack=0x00007fffccb1b9a0)(void*, void**, unsigned int), void*) + 138 at gcinfodecoder.cpp:1008 frame #11: 0x00000000005d75e3 ConsoleApp1GcInfoDecoder::EnumerateLiveSlots(this=0x00007fffccb1b8c8, pRD=0x00007fffccb1bae0, reportScratchSlots=false, inputFlags=0, pCallBack=(ConsoleApp1EnumGcRefsCallback(void*, void**, unsigned int) at gcrhenv.cpp:505), hCallBack=0x00007fffccb1b9a0)(void*, void**, unsigned int), void*) + 8707 at gcinfodecoder.cpp:957 frame #12: 0x00000000005db9a9 ConsoleApp1UnixNativeCodeManager::EnumGcRefs(this=0x0000000000dbe850, pMethodInfo=0x00007fffccb1bb78, safePointAddress=0x0000000000673d86, pRegisterSet=0x00007fffccb1bae0, hCallback=0x00007fffccb1b9a0) + 473 at UnixNativeCodeManager.cpp:153
    frame Initial population of CoreRT Runtime files. #13: 0x0000000000415bed ConsoleApp1RedhawkGCInterface::EnumGcRefs(pCodeManager=0x0000000000dbe850, pMethodInfo=0x00007fffccb1bb78, safePointAddress=0x0000000000673d86, pRegisterSet=0x00007fffccb1bae0, pfnEnumCallback=0x000000000049de10, pvCallbackData=0x00007fffccb1bfc8) + 141 at gcrhenv.cpp:534 frame #14: 0x000000000043611c ConsoleApp1Thread::GcScanRootsWorker(this=0x00007fffccb1d5e8, pfnEnumCallback=0x000000000049de10, pvCallbackData=0x00007fffccb1bfc8, frameIterator=0x00007fffccb1bac0) + 572 at thread.cpp:491
    frame Set AllowUnsafeBlocks irrespective of build configuration #15: 0x0000000000435eb4 ConsoleApp1Thread::GcScanRoots(this=0x00007fffccb1d5e8, pfnEnumCallback=0x000000000049de10, pvCallbackData=0x00007fffccb1bfc8) + 132 at thread.cpp:408 frame #16: 0x0000000000418f35 ConsoleApp1GCToEEInterface::GcScanRoots(fn=(ConsoleApp1WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int) at gc.cpp:33749), condemned=2, max_gen=2, sc=0x00007fffccb1bfc8)(Object**, ScanContext*, unsigned int), int, int, ScanContext*) + 501 at gcrhscan.cpp:85 frame #17: 0x00000000005c3fb9 ConsoleApp1GCScan::GcScanRoots(fn=(ConsoleApp1WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int) at gc.cpp:33749), condemned=2, max_gen=2, sc=0x00007fffccb1bfc8)(Object**, ScanContext*, unsigned int), int, int, ScanContext*) + 41 at gcscan.cpp:170 frame #18: 0x0000000000479a4c ConsoleApp1WKS::gc_heap::mark_phase(condemned_gen_number=2, mark_only_p=NO) + 2060 at gc.cpp:19592
    frame Unify caching pattern between EcmaMethod and EcmaField #19: 0x00000000004713d7 ConsoleApp1WKS::gc_heap::gc1() + 519 at gc.cpp:15262 frame #20: 0x000000000048e3d3 ConsoleApp1WKS::gc_heap::garbage_collect(n=0) + 3395 at gc.cpp:16853
    frame Wire up CppCodeGen into ILToNative #21: 0x0000000000463051 ConsoleApp1WKS::GCHeap::GarbageCollectGeneration(this=0x0000000000db61e0, gen=0, reason=reason_alloc_loh) + 2049 at gc.cpp:35188 frame #22: 0x00000000004681ff ConsoleApp1WKS::gc_heap::try_allocate_more_space(acontext=0x00007fffccb1c9b0, size=131128, gen_number=3) + 1503 at gc.cpp:13066
    frame Make ThreadSafeFlags public #23: 0x0000000000468373 ConsoleApp1WKS::gc_heap::allocate_more_space(acontext=0x00007fffccb1c9b0, size=131128, alloc_generation_number=3) + 35 at gc.cpp:13362 frame #24: 0x00000000004d9a74 ConsoleApp1WKS::gc_heap::allocate_large_object(jsize=131096, alloc_bytes=0x00007fffccb1d600) + 500 at gc.cpp:30569
    frame Make build.cmd more like the build.cmd in CoreCLR repo #25: 0x00000000004e1ace ConsoleApp1WKS::GCHeap::Alloc(this=0x0000000000db61e0, context=0x00007fffccb1d5e8, size=131096, flags=0) + 446 at gc.cpp:34542 frame #26: 0x0000000000415933 ConsoleApp1::RhpGcAlloc(pEEType=0x0000000000cad100, uFlags=0, cbSize=131096, pTransitionFrame=0x00007fffccb1cb18) + 211 at gcrhenv.cpp:273
    frame Enhance virtual function resolution logic to be roughly correct. #27: 0x00000000005e49ca ConsoleApp1RhpNewArrayRare + 54 at unixasmmacrosamd64.inc:651 frame #28: 0x00000000005fd198 ConsoleApp1 frame #29: 0x0000000000686ce3 ConsoleApp1 frame #30: 0x000000000064b9fd ConsoleApp1 frame #31: 0x000000000061a111 ConsoleApp1 frame #32: 0x0000000000673d86 ConsoleApp1 frame #33: 0x000000000062d949 ConsoleApp1 frame #34: 0x0000000000622f80 ConsoleApp1 frame #35: 0x00000000006922d8 ConsoleApp1 frame #36: 0x000000000067db78 ConsoleApp1 frame #37: 0x00007ffff6d93184 libpthread.so.0start_thread(arg=0x00007fffccb1d700) + 196 at pthread_create.c:312
    frame Fix project GUID in the ProjectReference from ILToNative #38: 0x00007ffff6ac037d libc.so.6`__clone + 109 at clone.S:111

[sandreenko]

I checked that if we spill all gc refs before each call the issue still occurs.
Did anybody found the bad method name?

[jkotas]

It is call to CoreLibNative_GetTickCount64 above. The codegen part of the spilling works fine. The problem is that the spilling is not reflected in the GCInfo correctly. The registers are still reported as alive during RhpPInvoke call, and they are reported dead right after the RhpPInvoke call.

    0x1001e5b07 <+275>: callq  0x1001be7cc               ; RhpPInvoke
    0x1001e5b0c <+280>: callq  0x1001c0010               ; ::CoreLibNative_GetTickCount64() at pal_time.cpp:107
    0x1001e5b11 

In this example, we use 0x1001e5b0c for the GC reporting during the PInvoke. This IP still has the registers reported as alive.

I can think of several options on how to fix this:

Option 1: Make sure that the registers are reported dead in GCInfo before the RhpPInvoke helper. The following code seems to be taking care of it for the regular PInvoke callsites. Does it need to be changed to emit the label for RhpPInvoke helper instead, or in addition to the regular callsite, when JIT_FLAG_USE_PINVOKE_HELPERS is set?

    // For a pinvoke to unmanaged code we emit a label to clear
    // the GC pointer state before the callsite.
    // We can't utilize the typical lazy killing of GC pointers
    // at (or inside) the callsite.
    if (call->IsUnmanaged())
    {
        genDefineTempLabel(genCreateTempLabel());
    }

Option 2: Add argument to RhpPInvoke helper that describes the actual IP of the PInvoke callsite return. It is what happens for regular inlined PInvokes - look for genPendingCallLabel. The address of this pending label would be used as the RhpPInvoke helper argument.

If we went with this option, we would use 0x1001e5b11 IP for the GC reporting during the PInvoke in the example above and everything would be good.

Option 3: Change the CoreRT stackwalker to track where the IP came from and pass this information into the ICodeManager::EnumGcRefs to let it adjust the IP accordingly. We would bump the IP for reporting when we know that it is coming from PInvoke. There is similar mechanism for hardware exceptions today - look for RemapHardwareFaultToGCSafePoint. This would mean generalizing this mechanism for other cases. I think this would be my least favorite option.

@sandreenko Could you please look into feasibility of options 1 and 2 on the JIT side?