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

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

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 21 (19 by maintainers)

Most upvoted comments

Just based on the remote processes’ stacks above, I think it’s more likely this is a deadlock.

stephentoub on Dec 2, 2020

It is a classic A-B B-A deadlock:

Main thread is waiting for this lock:

0a 0117dafc 72c37cda coreclr!AwareLock::Enter+0x167 [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2404] 
0b (Inline) -------- coreclr!Object::EnterObjMonitor+0x8 [F:\workspace\_work\1\s\src\coreclr\src\vm\object.h @ 277] 
0c 0117dbd4 72c3d3fd coreclr!JIT_MonEnter_Helper+0xed [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3665] 
0d 0117dd10 725d660a coreclr!JIT_MonReliableEnter_Portable+0x3fd [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3713] 
0e 0117dd40 725db014 System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventProviderType, Int32, Int32, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords, System.Collections.Generic.IDictionary`2<System.String,System.String>)+0xa6 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 2385] 
0f 0117dd78 08a41d7b System_Private_CoreLib!System.Diagnostics.Tracing.EventListener.EnableEvents(System.Diagnostics.Tracing.EventSource, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords, System.Collections.Generic.IDictionary`2<System.String,System.String>)+0x30 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3876] 
10 0117ddc4 08a41785 System_Buffers_Tests!System.Diagnostics.Tracing.TestEventListener.EnableEventSource(System.Diagnostics.Tracing.EventSource, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)+0xcb
11 0117dec4 08a414b4 System_Buffers_Tests!System.Diagnostics.Tracing.TestEventListener.AddSource(System.String, System.Nullable`1<System.Guid>, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)+0x2ad
12 0117df08 08a406b8 System_Buffers_Tests!System.Diagnostics.Tracing.TestEventListener.AddSource(System.String, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords)+0x64
13 0117df34 08a404ec System_Buffers_Tests!System.Diagnostics.Tracing.TestEventListener..ctor(System.String, System.Diagnostics.Tracing.EventLevel, System.Nullable`1<Double>)+0xc8
14 0117df9c 08bfff4f System_Buffers_Tests!System.Buffers.ArrayPool.Tests.ArrayPoolTest.RunWithListener(System.Action, System.Diagnostics.Tracing.EventLevel, System.Action`1<System.Diagnostics.Tracing.EventWrittenEventArgs>)+0x9c
15 0117dfd8 72e54161 System_Buffers_Tests!System.Buffers.ArrayPool.Tests.ArrayPoolUnitTests+<>c.<ReturnBufferFiresDiagnosticEvent>b__35_0()+0xf7
16 0117dfe4 72b58c9d coreclr!CallDescrWorkerInternal+0x34

The lock is taken by this thread that is waiting on a lock taken by the main thread:

09 08e9db20 72af662c coreclr!AwareLock::EnterEpilog+0x41 [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2501] 
0a 08e9dba8 72c37cda coreclr!AwareLock::Enter+0x167 [F:\workspace\_work\1\s\src\coreclr\src\vm\syncblk.cpp @ 2404] 
0b (Inline) -------- coreclr!Object::EnterObjMonitor+0x8 [F:\workspace\_work\1\s\src\coreclr\src\vm\object.h @ 277] 
0c 08e9dc80 72c3d3fd coreclr!JIT_MonEnter_Helper+0xed [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3665] 
0d 08e9ddbc 724cf577 coreclr!JIT_MonReliableEnter_Portable+0x3fd [F:\workspace\_work\1\s\src\coreclr\src\vm\jithelpers.cpp @ 3713] 
0e 08e9ddc8 08a40cb9 System_Private_CoreLib!System.Threading.Monitor.Enter(System.Object, Boolean ByRef)+0x13 [/_/src/coreclr/src/System.Private.CoreLib/src/System/Threading/Monitor.CoreCLR.cs @ 48] 
0f 08e9de28 725d89e8 System_Buffers_Tests!System.Diagnostics.Tracing.TestEventListener.OnEventSourceCreated(System.Diagnostics.Tracing.EventSource)+0x59
10 08e9de58 725db2d6 System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.AddListener(System.Diagnostics.Tracing.EventListener)+0xa4 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 3318] 
11 08e9dea0 725d4255 System_Private_CoreLib!System.Diagnostics.Tracing.EventListener.AddEventSource(System.Diagnostics.Tracing.EventSource)+0x196 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 4010] 
12 08e9defc 724eb41a System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.Initialize(System.Guid, System.String, System.String[])+0x169 [/_/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @ 1502] 
13 08e9df40 724eb9a1 System_Private_CoreLib!System.Threading.PortableThreadPoolEventSource..ctor()+0xb2 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPoolEventSource.cs @ 84] 
14 08e9df54 72e54161 System_Private_CoreLib!System.Threading.PortableThreadPoolEventSource..cctor()+0x11 [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPoolEventSource.cs @ 293] 
15 08e9df54 72b58c9d coreclr!CallDescrWorkerInternal+0x34

jkotas on Dec 2, 2020

I can take a look at fixing this @safern. Please tag/assign me in the issue you open.

sywhang on Dec 2, 2020