Recurring test failures in tracing due to class loader alloc tracker heap corruption

[VincentBu]

Run: runtime-coreclr jitstress-isas-x86 20210814.1

Failed test:

CoreCLR windows x86 Checked jitstress_isas_x86_nopopcnt @ Windows.10.Amd64.Open
- tracing\\eventpipe\\reverseouter\\reverseouter\\reverseouter.cmd

CoreCLR windows x86 Checked jitstress_isas_x86_nossse3 @ Windows.10.Amd64.Open
- tracing\\eventpipe\\reverseouter\\reverseouter\\reverseouter.cmd

Error message:

cmdLine:C:\h\w\B11509CA\w\BA4B09A3\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.cmd Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 8/14/2021 11:39:39 PM, end: 8/15/2021 12:09:39 AM)

Return code:      -100
Raw output file:      C:\h\w\B11509CA\w\BA4B09A3\uploads\Reports\tracing.eventpipe\reverseouter\reverseouter\reverseouter.output.txt
Raw output:
BEGIN EXECUTION
"C:\h\w\B11509CA\p\corerun.exe" -p "System.Reflection.Metadata.MetadataUpdater.IsSupported=false" reverseouter.dll
0.0s: ::== Running test: TEST_ReverseConnectionCanRecycleWhileTracing
0.2s: Server name is 'DOTNET_TRACE_TESTS_detbzyk5.yth'
1.0s: running sub-process: C:\h\w\B11509CA\p\corerun.exe C:\h\w\B11509CA\w\BA4B09A3\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll 0
2.2s: subprocess started: True
2.3s: subprocess PID: 8652
4.4s: Starting EventPipeSession over standard connection
4.6s: Waiting for connection
4.7s: Started EventPipeSession over standard connection with session id: 0x8a232a0
4.8s: Got a connection
4.8s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
4.9s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
4.9s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a connection
5.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_detbzyk5.yth
5.0s: { Magic=System.Byte[]; ClrInstanceId=00d25c2b-aef8-4f44-b2e1-eac3813f1b3f; ProcessId=8652; Unused=0; }
5.0s: Waiting for connection
5.0s: Got a conne


Stack trace
   at tracing_eventpipe._reverseouter_reverseouter_reverseouter_._reverseouter_reverseouter_reverseouter_cmd()

Runfo Tracking Issue: reverseouter tests

Build	Definition	Kind	Run Name

Build Result Summary

Day Hit Count	Week Hit Count	Month Hit Count
0	0	0

[josalem]

This and #57254 appear to be the same failure:

        6.0s: Assert failure(PID 8652 [0x000021cc], Thread: 6180 [0x1824]): Consistency check failed: Linked list pointer == NULL, memory corruption likely
        6.0s: FAILED: pDebugBlock != nullptr
        6.0s: CORECLR! CHECK::Trigger + 0x310 (0x70b88f0d)
        6.0s: CORECLR! AllocMemTracker::~AllocMemTracker + 0x24C (0x70b8b6b1)
        6.0s: CORECLR! IBCLoggerAwareAllocMemTracker::~IBCLoggerAwareAllocMemTracker + 0xDC (0x708ff85d)
        6.0s: CORECLR! ClassLoader::DoIncrementalLoad + 0x437 (0x706c677a)
        6.0s: CORECLR! ClassLoader::LoadTypeHandleForTypeKey_Body + 0x894 (0x706cf4c8)
        6.0s: CORECLR! ClassLoader::LoadTypeHandleForTypeKey + 0x19A (0x706ce70c)
        6.0s: CORECLR! ClassLoader::LoadTypeDefThrowing + 0x8A5 (0x706ce38c)
        6.0s: CORECLR! ClassLoader::LoadTypeDefOrRefThrowing + 0x6E1 (0x706cd96f)
        6.0s: CORECLR! SigPointer::GetTypeHandleThrowing + 0x926 (0x707fe472)

This looks like it is the same failure that was happening in #54469.

[josalem]

Popped open the dumps from these failures.

Looks to be coming from here (the destructor on the alloc tracker being hit at the end of the scope):

runtime/src/coreclr/vm/clsload.cpp

Lines 3123 to 3133 in a1eefbb

	case CLASS_LOAD_BEGIN :
	{
	IBCLoggerAwareAllocMemTracker amTracker;
	typeHnd = CreateTypeHandleForTypeKey(pTypeKey, &amTracker);
	CONSISTENCY_CHECK(!typeHnd.IsNull());
	TypeHandle published = PublishType(pTypeKey, typeHnd);
	if (published == typeHnd)
	amTracker.SuppressRelease();
	typeHnd = published;
	}
	break;

The scope of the tracking seems to be limited to this class load if I understand the alloc tracker code correctly.

We're reaching this during loading from an R2R image and doing fixups:

@davidwrighton or @mangod9 or @janvorli is there something I should take a look at that might give us more information? I have the MD for the method being loaded: it's System.Diagnostics.Tracing.EventProvider.GetDataFromController which is coming from SPCL.

[josalem]

Let me amend that previous comment:

The method being reverse p/invoked is System.Diagnostics.Tracing.EventProvider.GetDataFromController, but the type being loaded as part of the fixup when the failure happens is System.Globalization.NumberFormatInfo.

[josalem]

I'm unable to reproduce this locally. @hoyosjs helped me scrape some more stats about these failures:

• overwhelming majority are win-x86, but there are a couple win-arm32 failures as well
• all on Windows
• checked build
• no tiered compilation
• 12 failures in the last 10 days (~1 per day)
• happens across multiple tracing/eventing tests since they all end reverse p/invoking the same way

There is at least one example of this failure happening in a CI run: https://dev.azure.com/dnceng/public/_build/results?buildId=1285558&view=ms.vss-test-web.build-test-results-tab&runId=37949368&resultId=110729&paneView=debug

Looking at the failure there, it gets a little farther, but fails to load a different type (System.Numerics.Vector). The critical bit here, is that this failure doesn't involve CG2 while the rest seemingly are all R2R images. This means the failure happens under the JIT as well.

The node in the linked list of allocations that is messed up always seems to be coming from the same place:

runtime/src/coreclr/vm/methodtablebuilder.cpp

Lines 11671 to 11683 in 2144431

	BYTE *
	MethodTableBuilder::AllocateFromLowFrequencyHeap(S_SIZE_T cbMem)
	{
	CONTRACTL
	{
	THROWS;
	GC_NOTRIGGER;
	MODE_ANY;
	}
	CONTRACTL_END;
	return (BYTE *)GetMemTracker()->Track(
	GetLoaderAllocator()->GetLowFrequencyHeap()->AllocMem(cbMem));
	}