[GCStress] JIT/Methodical/tailcall/_il_dbgreference_i Assert failure SanityCheck()

[echesakov]

export COMPlus_TieredCompilation=0
export COMPlus_DbgEnableMiniDump=1
export COMPlus_DbgMiniDumpName=$HELIX_DUMP_FOLDER/coredump.%d.dmp
export COMPlus_GCStress=0xC

    JIT/Methodical/tailcall/_il_dbgreference_i/_il_dbgreference_i.sh [FAIL]
      Unhandled exception. 
      Assert failure(PID 2769 [0x00000ad1], Thread: 2769 [0x0ad1]): SanityCheck()
          File: /__w/1/s/src/coreclr/src/vm/methodtable.cpp Line: 9367
          Image: /root/helix/work/correlation/corerun
      
      /root/helix/work/workitem/JIT/Methodical/tailcall/_il_dbgreference_i/_il_dbgreference_i.sh: line 356:  2769 Aborted                 $LAUNCHER $ExePath "${CLRTestExecutionArguments[@]}"
      
      Return code:      1
      Raw output file:      /root/helix/work/workitem/JIT/Methodical/Reports/JIT.Methodical/tailcall/_il_dbgreference_i/_il_dbgreference_i.output.txt
      Raw output:
      BEGIN EXECUTION
      /root/helix/work/correlation/corerun _il_dbgreference_i.dll ''
      2 Gathering state for process 2769 corerun
      Writing minidump with heap to file /home/helixbot/dotnetbuild/dumps/coredump.2769.dmp
      Written 55345152 bytes (13512 pages) to core file
      Dump successfully written
      Expected: 100
      Actual: 134
      END EXECUTION - FAILED

https://dev.azure.com/dnceng/public/_build/results?buildId=793659&view=results
https://helix.dot.net/api/2019-06-17/jobs/d2e0c1f9-e5dc-4d0c-9252-d4f2d7fe271c/workitems/JIT.Methodical/console

[BruceForstall]

Between two runs of gcstress0x3-gcstress0xc and gcstress-extra, I grabbed four core dumps.

I was able to repro on Windows arm32, but not under a debugger (at least not yet).

I finally got a stack trace from gdb from a core dump:

(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0xe8f01caa in __waitpid (pid=0xb0d, stat_loc=0xffe3f150, options=0x0) at ../sysdeps/unix/sysv/linux/waitpid.c:30
#2  0xe8a3a974 in PROCCreateCrashDump (argv=<optimized out>) at /__w/1/s/src/coreclr/src/pal/src/thread/process.cpp:3336
#3  0xe8a38ad0 in PROCAbort () at /__w/1/s/src/coreclr/src/pal/src/thread/process.cpp:3471
#4  0xe8a3899c in RaiseFailFastException (pExceptionRecord=<optimized out>, pContextRecord=<optimized out>, dwFlags=<optimized out>) at /__w/1/s/src/coreclr/src/pal/src/thread/process.cpp:1395
#5  0xe88da38a in TerminateOnAssert () at /__w/1/s/src/coreclr/src/utilcode/debug.cpp:189
#6  _DbgBreakCheck (szFile=0xe8a915c6 "/__w/1/s/src/coreclr/src/vm/methodtable.cpp", iLine=0x2497, szExpr=0xe8b05722 "SanityCheck()", fConstrained=<optimized out>) at /__w/1/s/src/coreclr/src/utilcode/debug.cpp:424
#7  0xe88da822 in _DbgBreakCheckNoThrow (szFile=0xe8a915c6 "/__w/1/s/src/coreclr/src/vm/methodtable.cpp", iLine=0x2497, szExpr=0xe8b05722 "SanityCheck()", fConstrained=0x0) at /__w/1/s/src/coreclr/src/utilcode/debug.cpp:534
#8  0xe88daaec in DbgAssertDialog (szFile=0xe8a915c6 "/__w/1/s/src/coreclr/src/vm/methodtable.cpp", iLine=0x2497, szExpr=0x0) at /__w/1/s/src/coreclr/src/pal/inc/pal.h:3341
#9  0xe869e070 in MethodTable::Validate (this=0xdec21a8) at /__w/1/s/src/coreclr/src/vm/methodtable.cpp:9370
#10 0xe86a0e10 in Object::ValidateInner (this=0xe2e1ff64, bDeep=0x1, bVerifyNextHeader=0x1, bVerifySyncBlock=0x1) at /__w/1/s/src/coreclr/src/vm/object.cpp:542
#11 0xe889bd48 in WKS::GCHeap::Promote (ppObject=0xffe42150, sc=<optimized out>, flags=0x1) at /__w/1/s/src/coreclr/src/gc/gc.cpp:36336
#12 0xe883ab3a in GcInfoDecoder::ReportSlotToGC (this=<optimized out>, slotDecoder=..., slotIndex=<optimized out>, pRD=<optimized out>, reportScratchSlots=<optimized out>, inputFlags=<optimized out>, pCallBack=<optimized out>,
    hCallBack=<optimized out>) at /__w/1/s/src/coreclr/src/inc/gcinfodecoder.h:678
#13 GcInfoDecoder::ReportUntrackedSlots (this=0xffe3f4b8, slotDecoder=..., pRD=0xffe3f990, inputFlags=0x0, pCallBack=0xe8769ae1 <GcEnumObject(void*, OBJECTREF*, unsigned int)>, hCallBack=0xffe3ff74)
    at /__w/1/s/src/coreclr/src/vm/gcinfodecoder.cpp:1019
#14 GcInfoDecoder::EnumerateLiveSlots (this=0xffe3f4b8, pRD=0xffe3f990, reportScratchSlots=0x0, inputFlags=<optimized out>, pCallBack=0xe8769ae1 <GcEnumObject(void*, OBJECTREF*, unsigned int)>, hCallBack=0xffe3ff74)
    at /__w/1/s/src/coreclr/src/vm/gcinfodecoder.cpp:968
#15 0xe862e39a in EECodeManager::EnumGcRefs (this=<optimized out>, pRD=0xffe3f990, pCodeInfo=0xffe3f8b4, flags=0x0, pCallBack=0xe8769ae1 <GcEnumObject(void*, OBJECTREF*, unsigned int)>, hCallBack=0xffe3ff74,
    relOffsetOverride=0xffffffff) at /__w/1/s/src/coreclr/src/vm/eetwain.cpp:5149
#16 0xe8769e9e in GcStackCrawlCallBack (pCF=0xffe3f698, pData=0xffe3ff74) at /__w/1/s/src/coreclr/src/vm/gcenv.ee.common.cpp:282
#17 0xe86c63a0 in Thread::MakeStackwalkerCallback (this=0xded9368, pCF=0xffe3f698, pCallback=0xe8769c0d <GcStackCrawlCallBack(CrawlFrame*, void*)>, pData=0xffe3ff74, uFramesProcessed=0x10)
    at /__w/1/s/src/coreclr/src/vm/stackwalk.cpp:833
#18 0xe86c6590 in Thread::StackWalkFramesEx (this=0xded9368, pRD=0xffe3f990, pCallback=0xe8769c0d <GcStackCrawlCallBack(CrawlFrame*, void*)>, pData=0xffe3ff74, flags=0x8500, pStartFrame=0x0)
    at /__w/1/s/src/coreclr/src/vm/stackwalk.cpp:913
#19 0xe86c6d5e in Thread::StackWalkFrames (this=0xded9368, pCallback=0xe8769c0d <GcStackCrawlCallBack(CrawlFrame*, void*)>, pData=0xffe3ff74, flags=0x8500, pStartFrame=0x0) at /__w/1/s/src/coreclr/src/vm/stackwalk.cpp:996
#20 0xe8767026 in ScanStackRoots (pThread=0xded9368, fn=0xe889bcc5 <WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int)>, sc=0xffe40050) at /__w/1/s/src/coreclr/src/vm/gcenv.ee.cpp:147
#21 0xe8766d7c in GCToEEInterface::GcScanRoots (fn=0xe889bcc5 <WKS::GCHeap::Promote(Object**, ScanContext*, unsigned int)>, condemned=0x2, max_gen=0x2, sc=0xffe40050) at /__w/1/s/src/coreclr/src/vm/gcenv.ee.cpp:231
#22 0xe8892358 in WKS::gc_heap::mark_phase (condemned_gen_number=<optimized out>, mark_only_p=0x0) at /__w/1/s/src/coreclr/src/gc/gc.cpp:20745
#23 0xe888ff8c in WKS::gc_heap::gc1 () at /__w/1/s/src/coreclr/src/gc/gc.cpp:16684
#24 0xe8897d52 in WKS::gc_heap::garbage_collect (n=<optimized out>) at /__w/1/s/src/coreclr/src/gc/gc.cpp:18252
#25 0xe888b52c in WKS::GCHeap::GarbageCollectGeneration (this=<optimized out>, gen=0x2, reason=<optimized out>) at /__w/1/s/src/coreclr/src/gc/gc.cpp:37744
#26 0xe88ac190 in WKS::GCHeap::GarbageCollectTry (this=<optimized out>, generation=<optimized out>, low_memory_p=<optimized out>, mode=<optimized out>) at /__w/1/s/src/coreclr/src/gc/gc.cpp:37002
#27 WKS::GCHeap::GarbageCollect (this=<optimized out>, generation=<optimized out>, low_memory_p=<optimized out>, mode=<optimized out>) at /__w/1/s/src/coreclr/src/gc/gc.cpp:36936
#28 0xe88ab496 in WKS::GCHeap::StressHeap (this=0xde9f058, context=<optimized out>) at /__w/1/s/src/coreclr/src/gc/gc.cpp:36590
#29 0xe87667fc in DoGcStress (regs=0xdefaee0, nativeCodeVersion=...) at /__w/1/s/src/coreclr/src/vm/gccover.cpp:1714
#30 0xe87663da in OnGcCoverageInterrupt (regs=0xdefaee0) at /__w/1/s/src/coreclr/src/vm/gccover.cpp:1347
#31 0xe86382ba in IsGcMarker (pContext=0xdefaee0, pExceptionRecord=<optimized out>) at /__w/1/s/src/coreclr/src/vm/excep.cpp:6495
#32 0xe882eec8 in HandleHardwareException (ex=0xffe405f0) at /__w/1/s/src/coreclr/src/vm/exceptionhandling.cpp:5124
#33 0xe89e3ec0 in SEHProcessException (exception=0xffe405f0) at /__w/1/s/src/coreclr/src/pal/src/exception/seh.cpp:267
#34 0xe89e54fa in common_signal_handler (code=<optimized out>, siginfo=<optimized out>, sigcontext=0xffe40938, numParams=<optimized out>) at /__w/1/s/src/coreclr/src/pal/src/exception/signal.cpp:898
#35 0xe89e4bdc in sigill_handler (code=0x4, siginfo=0xffe408b8, context=0xffe40938) at /__w/1/s/src/coreclr/src/pal/src/exception/signal.cpp:352
#36 <signal handler called>
#37 0xe2517310 in ?? ()
#38 0xe251730a in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[jakobbotsch]

This test has to pass by-refs through the arg buffer. Could it be the following assumption that is not ok on ARM32 when we are loading the by-ref from the arg buffer?

runtime/src/coreclr/src/vm/tailcallhelp.cpp

Lines 635 to 640 in 2d463ee

	if (tyHnd.IsByRef())
	{
	// Note: we can use an "untracked" ldind.i here even with byrefs because
	// we are loading between two tracked positions.
	stream->EmitLDIND_I();
	}

Note also that since #41206 we are no longer loading from the arg buffer into a by-ref typed local first. I wonder if this could have any adverse effects as well. cc @jkotas

[jkotas]

Note: we can use an "untracked" ldind.i here even with byrefs

Is this assumption ever ok? This looks super fragile at best. This may need to use ByReference<T> until we get first class support for byrefs.

[jakobbotsch]

I can look into making that change this weekend. IIRC I was initially using ByReference<T> but hitting asserts in the JIT. Should it be fine to replace the ldind.i with ldobj ByReference<byte> followed by accessing the Value property?

[jkotas]

I do not think you need ldobj ByReference<byte>. It should be enough to just replace ldind.i by the Value property.

[jakobbotsch]

Aha, this would probably have been my mistake last time around then. Is there a similar possibility for the store into the arg buffer?

[jkotas]

I think your best bet is to stay close to the patterns that ByReference<T> is used for today. Creating ByReference<T> is newobj ByReference<T> + stfld, but that does not work for the arg buffer. I would use newobj ByReference<T> + stdobj that is close enough.