System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests.RentBufferFiresRentedDiagnosticEvent failure

[janvorli]

The test failed in CI on my PR (with change unrelated to the issue):

    System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests.RentBufferFiresRentedDiagnosticEvent [FAIL]
      Half-way through waiting for remote process.
      Timed out at 9/30/2020 1:52:32 AM after 60000ms waiting for remote process.
      	Process ID: 23479
      	Handle: 904
      	Name: dotnet
      	MainModule: /home/helixbot/work/A64809A4/p/dotnet
      	StartTime: 9/30/2020 1:51:32 AM
      	TotalProcessorTime: 00:00:00.0100000
      
      Stack Trace:
        /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs(224,0): at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing)
        /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs(57,0): at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose()
        /_/src/libraries/System.Buffers/tests/ArrayPool/ArrayPoolTest.cs(44,0): at System.Buffers.ArrayPool.Tests.ArrayPoolTest.RemoteInvokeWithTrimming(Action action, Boolean trim)
        /_/src/libraries/System.Buffers/tests/ArrayPool/UnitTests.cs(404,0): at System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests.RentBufferFiresRentedDiagnosticEvent()

https://dev.azure.com/dnceng/public/_build/results?buildId=836124&view=ms.vss-test-web.build-test-results-tab&runId=26640246&resultId=172262&paneView=history

Runfo Tracking Issue: system.buffers.arraypool.tests.arraypoolunittests.rentbufferfiresrenteddiagnosticevent

Build	Definition	Kind	Run Name

Build Result Summary

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

Tagging subscribers to this area: @tannergooding, @pgovind, @jeffhandley
See info in area-owners.md if you want to be subscribed.

Tagging subscribers to this area: @tommcdon
See info in area-owners.md if you want to be subscribed.

[jkotas]

Given that this is diagnostic event test and that the process spent just 10ms of processor time, this is most likely event pipe race condition that results into a hand during startup.

[josalem]

I looked at the test:

runtime/src/libraries/System.Buffers/tests/ArrayPool/UnitTests.cs

Lines 402 to 419 in 642b7cb

	public static void RentBufferFiresRentedDiagnosticEvent()
	{
	RemoteInvokeWithTrimming(() =>
	{
	ArrayPool<byte> pool = ArrayPool<byte>.Create(maxArrayLength: 16, maxArraysPerBucket: 1);
	byte[] buffer = pool.Rent(16);
	pool.Return(buffer);
	Assert.Equal(1, RunWithListener(() => pool.Rent(16), EventLevel.Verbose, e =>
	{
	Assert.Equal(1, e.EventId);
	Assert.Equal(buffer.GetHashCode(), e.Payload[0]);
	Assert.Equal(buffer.Length, e.Payload[1]);
	Assert.Equal(pool.GetHashCode(), e.Payload[2]);
	}));
	});
	}

I don't think this would go through EventPipe. If I recall correctly, because this is a managed EventSource (System.Buffers.ArrayPoolEventSource), and it's being listened to by an EventListener, events should be written directly to the listener.

Looking at the history it looks like this is the first failure of this test in recent history as well. There isn't a dump of the remote executor process in AzDO/Helix, so we'll have to see if this happens again to get more details.

[jkotas]

According to the log, the process spent 10ms of processor time. 10ms of processor time is not enough to start executing managed code. I think this got stuck in the unmanaged runtime startup, most likely in the unmanaged eventpipe or tracing initialization - since it happened while executing tests that stress these components.

[josalem]

EventPipe should be dormant for this test. Since the event producer is a managed EventSource and the consumer is an EventListener in process, EventPipe shouldn't be doing anything out of the ordinary especially before managed code runs. All the eventing in this test is happening in managed code. I agree that something must have happened before managed code executed, though, I'm just not sure it was EventPipe.

Have we seen any similar failures where a RemoteExecutor based test fails on timeout with the remote process only executing for a few milliseconds?

[v-haren]

failed again in job:runtime 20201102.59

failed test: System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests.RentBufferFiresRentedDiagnosticEvent

net6.0-OSX-Release-x64-CoreCLR_checked-OSX.1013.Amd64.Open

Error message

Half-way through waiting for remote process.
Timed out at 11/2/2020 2:52:28 PM after 60000ms waiting for remote process.
Process ID: 25505
Handle: 1020
Name: dotnet
MainModule: /private/tmp/helix/working/B0640910/p/dotnet
StartTime: 11/2/2020 2:51:28 PM
TotalProcessorTime: 00:00:00.1841435


Stack trace
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose(Boolean disposing) in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 224
   at Microsoft.DotNet.RemoteExecutor.RemoteInvokeHandle.Dispose() in /_/src/Microsoft.DotNet.RemoteExecutor/src/RemoteInvokeHandle.cs:line 57
   at System.Buffers.ArrayPool.Tests.ArrayPoolTest.RemoteInvokeWithTrimming(Action action, Boolean trim) in /_/src/libraries/System.Buffers/tests/ArrayPool/ArrayPoolTest.cs:line 44
   at System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests.RentBufferFiresRentedDiagnosticEvent() in /_/src/libraries/System.Buffers/tests/ArrayPool/UnitTests.cs:line 404

[ViktorHofer]

This has happened recently again (i.e. in https://dev.azure.com/dnceng/public/_build/results?buildId=871598&view=ms.vss-test-web.build-test-results-tab&runId=27884432&resultId=158379&paneView=debug). Updated the issue to be live tracking via runfo.

[stephentoub]

We also saw #44037 failing very frequently recently; I disabled the test as it was taking out too many PRs, but it had a similar symptom.