Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress #38801

v-haren · 2020-07-06T06:30:30Z

failed in job: runtime-coreclr gcstress0x3-gcstress0xc 20200705.1

Error message

Assert failure(PID 5020 [0x0000139c], Thread: 4956 [0x135c]): Consistency check failed: Crst Level violation: Can't take level 9 lock CrstCodeVersioning because you already holding level 7 lock CrstThreadpoolWaitThreads
FAILED: false

CORECLR! CHECK::Trigger + 0x310 (0x6eb46aef)
CORECLR! CrstBase::IsSafeToTake + 0x30A (0x6ed35246)
CORECLR! CrstBase::Enter + 0x152 (0x6ed34d90)
CORECLR! CrstBase::AcquireLock + 0xB (0x6eb822fd)
CORECLR! CodeVersionManager::LockHolder::LockHolder + 0x25 (0x6eb95182)
CORECLR! EECodeInfo::GetNativeCodeVersion + 0xC7 (0x6edbb0ec)
CORECLR! EECodeInfo::GetSavedMethodCode + 0x8C (0x6edbb5a3)
CORECLR! UnwindStackFrame + 0xD3 (0x6ed71fd3)
CORECLR! StackFrameIterator::NextRaw + 0x5BD (0x6ee56a11)
CORECLR! StackFrameIterator::Next + 0x46 (0x6ee56410)
 File: F:\workspace\_work\1\s\src\coreclr\src\vm\crst.cpp Line: 766
 Image: C:\h\w\A7710905\p\CoreRun.exe


Return code: 1
Raw output file: C:\h\w\A7710905\w\9B3E08D1\e\tracing\eventpipe\Reports\tracing.eventpipe\reverseouter\reverseouter\reverseouter.output.txt
Raw output:
BEGIN EXECUTION
 "C:\h\w\A7710905\p\corerun.exe" reverseouter.dll 
 0.0s: ::== Running test: TEST_ReverseConnectionCanRecycleWhileTracing
 0.6s: Server name is 'DOTNET_TRACE_TESTS_cisldcsj.lqr'
 4.1s: running sub-process: C:\h\w\A7710905\p\CoreRun.exe C:\h\w\A7710905\w\9B3E08D1\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll 0
Expected: 100
Actual: -1073740286
END EXECUTION - FAILED
FAILED
Test Harness Exitcode is : 1
To run the test:
> set CORE_ROOT=C:\h\w\A7710905\p
> C:\h\w\A7710905\w\9B3E08D1\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.cmd
Expected: True
Actual: False


Stack trace
   at tracing_eventpipe._reverseouter_reverseouter_reverseouter_._reverseouter_reverseouter_reverseouter_cmd() in F:\workspace\_work\1\s\artifacts\tests\coreclr\Windows_NT.x86.Checked\TestWrappers\tracing.eventpipe\tracing.eventpipe.XUnitWrapper.cs:line 819

The text was updated successfully, but these errors were encountered:

ghost · 2020-07-06T06:30:32Z

Tagging subscribers to this area: @dotnet/gc
Notify danmosemsft if you want to be subscribed.

BruceForstall · 2020-07-06T19:30:41Z

@sywhang @josalem

Issue: dotnet#38801

Issue: #38801

josalem · 2020-07-27T19:06:49Z

I can't seem to get this to reproduce locally with COMPlus_gcstress=0xc and COMPlus_TieredCompilation=0. I'll try with a few different gcstress modes.

BruceForstall · 2020-07-27T19:12:02Z

Note the failure above was CoreCLR Windows_NT x86 Checked gcstress0xc @ Windows.10.Amd64.Open. It only seems to fail on x86.

Here's the latest failure (from this weekend, before #39937):
https://dev.azure.com/dnceng/public/_build/results?buildId=746110&view=ms.vss-test-web.build-test-results-tab

josalem · 2020-07-27T19:13:38Z

Looks like I got a repro under gcstress=0x3c, but not 0x3 or 0xc on their own.

 # ChildEBP RetAddr      
00 00b7be58 5bf46a9f     CoreCLR!DbgAssertDialog+0x20f [C:\git\runtime\src\coreclr\src\utilcode\debug.cpp @ 697] 
01 00b7befc 5c135696     CoreCLR!CHECK::Trigger+0x310 [C:\git\runtime\src\coreclr\src\utilcode\check.cpp @ 139] 
02 00b7bf90 5c1351e0     CoreCLR!CrstBase::IsSafeToTake+0x30a [C:\git\runtime\src\coreclr\src\vm\crst.cpp @ 761] 
03 00b7bfc0 5bf8229d     CoreCLR!CrstBase::Enter+0x152 [C:\git\runtime\src\coreclr\src\vm\crst.cpp @ 305] 
04 00b7bff4 5bf95112     CoreCLR!CrstBase::AcquireLock+0xb [C:\git\runtime\src\coreclr\src\vm\crst.h @ 188] 
05 (Inline) --------     CoreCLR!FunctionBase<CrstBase *,&CrstBase::AcquireLock,&CrstBase::ReleaseLock>::DoAcquire+0x6 [C:\git\runtime\src\coreclr\src\inc\holder.h @ 707] 
06 (Inline) --------     CoreCLR!BaseHolder<CrstBase *,FunctionBase<CrstBase *,&CrstBase::AcquireLock,&CrstBase::ReleaseLock>,0,&CompareDefault<CrstBase *> >::Acquire+0x6 [C:\git\runtime\src\coreclr\src\inc\holder.h @ 280] 
07 (Inline) --------     CoreCLR!BaseHolder<CrstBase *,FunctionBase<CrstBase *,&CrstBase::AcquireLock,&CrstBase::ReleaseLock>,0,&CompareDefault<CrstBase *> >::{ctor}+0x14 [C:\git\runtime\src\coreclr\src\inc\holder.h @ 247] 
08 (Inline) --------     CoreCLR!Holder<CrstBase *,&CrstBase::AcquireLock,&CrstBase::ReleaseLock,0,&CompareDefault<CrstBase *>,1>::{ctor}+0x14 [C:\git\runtime\src\coreclr\src\inc\holder.h @ 742] 
09 00b7bff4 5c1bad8c     CoreCLR!CodeVersionManager::LockHolder::LockHolder+0x25 [C:\git\runtime\src\coreclr\src\vm\codeversion.h @ 673] 
0a 00b7c070 5c1bb243     CoreCLR!EECodeInfo::GetNativeCodeVersion+0xc7 [C:\git\runtime\src\coreclr\src\vm\jitinterface.cpp @ 14351] 
0b 00b7c0ec 5c172573     CoreCLR!EECodeInfo::GetSavedMethodCode+0x8c [C:\git\runtime\src\coreclr\src\vm\jitinterface.cpp @ 14303] 
0c 00b7c174 5c2568fb     CoreCLR!UnwindStackFrame+0xd3 [C:\git\runtime\src\coreclr\src\vm\eetwain.cpp @ 4037] 
0d 00b7c1f0 5c2562fa     CoreCLR!StackFrameIterator::NextRaw+0x5bd [C:\git\runtime\src\coreclr\src\vm\stackwalk.cpp @ 2448] 
0e 00b7c4c0 5c257921     CoreCLR!StackFrameIterator::Next+0x46 [C:\git\runtime\src\coreclr\src\vm\stackwalk.cpp @ 1559] 
0f 00b7c4c0 5c257717     CoreCLR!Thread::StackWalkFramesEx+0x18a [C:\git\runtime\src\coreclr\src\vm\stackwalk.cpp @ 919] 
10 00b7c800 5c343b16     CoreCLR!Thread::StackWalkFrames+0x159 [C:\git\runtime\src\coreclr\src\vm\stackwalk.cpp @ 997] 
11 00b7c914 5c342176     CoreCLR!ScanStackRoots+0x195 [C:\git\runtime\src\coreclr\src\vm\gcenv.ee.cpp @ 147] 
12 00b7c934 5c5ae0ad     CoreCLR!GCToEEInterface::GcScanRoots+0xe4 [C:\git\runtime\src\coreclr\src\vm\gcenv.ee.cpp @ 226] 
13 00b7c990 5c5a824a     CoreCLR!WKS::gc_heap::mark_phase+0x1ad [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 20479] 
14 00b7c9b8 5c5a807c     CoreCLR!WKS::gc_heap::gc1+0x149 [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 16416] 
15 00b7c9d0 5c5996ea     CoreCLR!WKS::gc_heap::garbage_collect+0x3c2 [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 18002] 
16 00b7c9f8 5c5997dd     CoreCLR!WKS::GCHeap::GarbageCollectGeneration+0x21c [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 37428] 
17 00b7ca0c 5c59b45b     CoreCLR!WKS::GCHeap::GarbageCollectTry+0x55 [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 36680] 
18 00b7ca48 5c4747c8     CoreCLR!WKS::GCHeap::StressHeap+0x3db [C:\git\runtime\src\coreclr\src\gc\gc.cpp @ 36265] 
19 00b7cb08 5c474d9f     CoreCLR!Thread::PerformPreemptiveGC+0x1f2 [C:\git\runtime\src\coreclr\src\vm\threadsuspend.cpp @ 2527] 
1a 00b7cb80 5bf9bca9     CoreCLR!Thread::RareEnablePreemptiveGC+0xe4 [C:\git\runtime\src\coreclr\src\vm\threadsuspend.cpp @ 2571] 
1b 00b7cbac 5bf950ac     CoreCLR!GCHolderBase::EnterInternalPreemp+0x101 [C:\git\runtime\src\coreclr\src\vm\threads.h @ 5436] 
1c 00b7ccc0 5c2a150c     CoreCLR!GCPreemp::GCPreemp+0x22 [C:\git\runtime\src\coreclr\src\vm\threads.h @ 5683] 
1d 00b7ccc0 5c2a2819     CoreCLR!ThreadpoolMgr::CreateWaitThread+0x1f4 [C:\git\runtime\src\coreclr\src\vm\win32threadpool.cpp @ 2394] 
1e 00b7cd30 5c2a5601     CoreCLR!ThreadpoolMgr::FindWaitThread+0x9f [C:\git\runtime\src\coreclr\src\vm\win32threadpool.cpp @ 2329] 
1f 00b7cdac 5c2db050     CoreCLR!ThreadpoolMgr::RegisterWaitForSingleObject+0xaf [C:\git\runtime\src\coreclr\src\vm\win32threadpool.cpp @ 2248] 
20 00b7ce9c 5b2ff2c8     CoreCLR!ThreadPoolNative::CorRegisterWaitForSingleObject+0x210 [C:\git\runtime\src\coreclr\src\vm\comthreadpool.cpp @ 430] 
21 00b7cecc 0a84a50a     System_Private_CoreLib!System.Threading.ThreadPool.RegisterWaitForSingleObject(System.Threading.WaitHandle, System.Threading.WaitOrTimerCallback, System.Object, UInt32, Boolean, Boolean)+0xc4 [C:\git\runtime\src\coreclr\src\System.Private.CoreLib\src\System\Threading\ThreadPool.CoreCLR.cs @ 287] 
22 00b7cf10 0a847bd6     system_diagnostics_process!System.Diagnostics.Process.EnsureWatchingForExit()+0xe2*** WARNING: Unable to verify checksum for C:\git\runtime\artifacts\tests\coreclr\Windows_NT.x86.Checked\Tests\Core_Root\system.diagnostics.process.dll
 [C:\git\runtime\src\libraries\System.Diagnostics.Process\src\System\Diagnostics\Process.Windows.cs @ 147] 
23 00b7d01c 0a844fa7     system_diagnostics_process!System.Diagnostics.Process.StartWithCreateProcess(System.Diagnostics.ProcessStartInfo)+0xb9e [C:\git\runtime\src\libraries\System.Diagnostics.Process\src\System\Diagnostics\Process.Windows.cs @ 650] 
24 00b7d034 08ac7c21     system_diagnostics_process!System.Diagnostics.Process.Start()+0x117 [C:\git\runtime\src\libraries\System.Diagnostics.Process\src\System\Diagnostics\Process.cs @ 1230] 
25 00b7d0bc 08ac56f2     common!Tracing.Tests.Common.Utils+<RunSubprocess>d__4.MoveNext()+0x439*** WARNING: Unable to verify checksum for C:\git\runtime\artifacts\tests\coreclr\Windows_NT.x86.Checked\tracing\eventpipe\reverseouter\reverseouter\common.dll

26 00b7d0ec 08ac5683     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Tracing.Tests.Common.Utils+<RunSubprocess>d__4, common]](<RunSubprocess>d__4 ByRef)+0x42 [C:\git\runtime\src\libraries\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilderCore.cs @ 42] 
27 00b7d120 08ac508a     common!Tracing.Tests.Common.Utils.RunSubprocess(System.Reflection.Assembly, System.Collections.Generic.Dictionary`2<System.String,System.String>, System.Func`1<System.Threading.Tasks.Task>, System.Func`2<Int32,System.Threading.Tasks.Task>, System.Func`1<System.Threading.Tasks.Task>)+0x4b
28 00b7d170 08ac4eba     reverseouter!Tracing.Tests.ReverseValidation.ReverseValidation+<TEST_ReverseConnectionCanRecycleWhileTracing>d__0.MoveNext()+0x15a*** WARNING: Unable to verify checksum for C:\git\runtime\artifacts\tests\coreclr\Windows_NT.x86.Checked\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll

29 00b7d1a0 08ac4e50     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Tracing.Tests.Common.Utils+<RunSubprocess>d__4, common]](<RunSubprocess>d__4 ByRef)+0xfffff80a [C:\git\runtime\src\libraries\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilderCore.cs @ 63] 
2a 00b7d1b8 5c5bc2a1     reverseouter!Tracing.Tests.ReverseValidation.ReverseValidation.TEST_ReverseConnectionCanRecycleWhileTracing()+0x28
2b 00b7d1c4 5c2c05a1     CoreCLR!CallDescrWorkerInternal+0x34 [C:\git\runtime\src\coreclr\src\vm\i386\asmhelpers.asm @ 606] 
2c 00b7d5e4 5c2c06f9     CoreCLR!CallDescrWorker+0xd7 [C:\git\runtime\src\coreclr\src\vm\callhelpers.cpp @ 127] 
2d 00b7d668 5c44097c     CoreCLR!CallDescrWorkerWithHandler+0xf6 [C:\git\runtime\src\coreclr\src\vm\callhelpers.cpp @ 70] 
2e 00b7d6a8 5c43866d     CoreCLR!`CallDescrWorkerReflectionWrapper'::`3'::__Body::Run+0x45 [C:\git\runtime\src\coreclr\src\vm\reflectioninvocation.cpp @ 647] 
2f 00b7d6f0 5c43ed45     CoreCLR!CallDescrWorkerReflectionWrapper+0x31 [C:\git\runtime\src\coreclr\src\vm\reflectioninvocation.cpp @ 647] 
30 00b7d944 5b3a1eec     CoreCLR!RuntimeMethodHandle::InvokeMethod+0x965 [C:\git\runtime\src\coreclr\src\vm\reflectioninvocation.cpp @ 1243] 
31 00b7d970 0887b76b     System_Private_CoreLib!System.Reflection.RuntimeMethodInfo.Invoke(System.Object, System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)+0x64 [C:\git\runtime\src\coreclr\src\System.Private.CoreLib\src\System\Reflection\RuntimeMethodInfo.cs @ 399] 
32 00b7d9c8 088794aa     reverseouter!Tracing.Tests.ReverseValidation.ReverseValidation+<Main>d__1.MoveNext()+0x1cb
33 00b7d9f8 0887943e     System_Private_CoreLib!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start[[Tracing.Tests.Common.Utils+<RunSubprocess>d__4, common]](<RunSubprocess>d__4 ByRef)+0xffdb3dfa [C:\git\runtime\src\libraries\System.Private.CoreLib\src\System\Runtime\CompilerServices\AsyncMethodBuilderCore.cs @ 63] 
34 00b7da18 088793c7     reverseouter!Tracing.Tests.ReverseValidation.ReverseValidation.Main(System.String[])+0x2e
35 00b7da28 5c5bc2a1     reverseouter!Tracing.Tests.ReverseValidation.ReverseValidation.<Main>(System.String[])+0xf
36 00b7da34 5c2c05a1     CoreCLR!CallDescrWorkerInternal+0x34 [C:\git\runtime\src\coreclr\src\vm\i386\asmhelpers.asm @ 606] 
37 00b7de54 5c2c06f9     CoreCLR!CallDescrWorker+0xd7 [C:\git\runtime\src\coreclr\src\vm\callhelpers.cpp @ 127] 
38 00b7ded0 5c2c0d7e     CoreCLR!CallDescrWorkerWithHandler+0xf6 [C:\git\runtime\src\coreclr\src\vm\callhelpers.cpp @ 70] 
39 00b7e134 5c0b2a6f     CoreCLR!MethodDescCallSite::CallTargetWorker+0x64f [C:\git\runtime\src\coreclr\src\vm\callhelpers.cpp @ 552] 
3a (Inline) --------     CoreCLR!MethodDescCallSite::Call_RetArgSlot+0x99 [C:\git\runtime\src\coreclr\src\vm\callhelpers.h @ 458] 
3b 00b7e25c 5c0b2668     CoreCLR!RunMainInternal+0x1b0 [C:\git\runtime\src\coreclr\src\vm\assembly.cpp @ 1455] 
3c 00b7e298 5c0b2716     CoreCLR!``RunMain'::`29'::__Body::Run'::`5'::__Body::Run+0x40 [C:\git\runtime\src\coreclr\src\vm\assembly.cpp @ 1525] 
3d 00b7e2ec 5c0b2840     CoreCLR!`RunMain'::`29'::__Body::Run+0x5d [C:\git\runtime\src\coreclr\src\vm\assembly.cpp @ 1525] 
3e 00b7e34c 5c0af182     CoreCLR!RunMain+0xc5 [C:\git\runtime\src\coreclr\src\vm\assembly.cpp @ 1525] 
3f 00b7e6a8 5c133539     CoreCLR!Assembly::ExecuteMainMethod+0x1ba [C:\git\runtime\src\coreclr\src\vm\assembly.cpp @ 1635] 
40 00b7e810 5bf2d4d2     CoreCLR!CorHost2::ExecuteAssembly+0x4a9 [C:\git\runtime\src\coreclr\src\vm\corhost.cpp @ 385] 
41 00b7e870 00f0a69a     CoreCLR!coreclr_execute_assembly+0x92 [C:\git\runtime\src\coreclr\src\dlls\mscoree\unixinterface.cpp @ 418] 
42 00b7e894 00f0a5e6     CoreRun!HostEnvironment::ExecuteAssembly+0x2a [C:\git\runtime\src\coreclr\src\hosts\corerun\corerun.cpp @ 351] 
43 00b7ec60 00f0ecaa     CoreRun!ExecuteAssembly+0x35a [C:\git\runtime\src\coreclr\src\hosts\corerun\corerun.cpp @ 636] 
44 00b7faf0 00f0f876     CoreRun!TryRun+0x3ed [C:\git\runtime\src\coreclr\src\hosts\corerun\corerun.cpp @ 773] 
45 00b7fb40 00f2d053     CoreRun!wmain+0x98 [C:\git\runtime\src\coreclr\src\hosts\corerun\corerun.cpp @ 854] 
46 00b7fb60 00f2cf27     CoreRun!invoke_main+0x33 [D:\agent\_work\7\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 90] 
47 00b7fbbc 00f2cdcd     CoreRun!__scrt_common_main_seh+0x157 [D:\agent\_work\7\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 288] 
48 00b7fbc4 00f2d0b8     CoreRun!__scrt_common_main+0xd [D:\agent\_work\7\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 331] 
49 00b7fbcc 76076359     CoreRun!wmainCRTStartup+0x8 [D:\agent\_work\7\s\src\vctools\crt\vcstartup\src\startup\exe_wmain.cpp @ 17] 
4a 00b7fbdc 77be7c24     KERNEL32!BaseThreadInitThunk+0x19 [base\win32\client\thread.c @ 64] 
4b 00b7fc38 77be7bf4     ntdll!__RtlUserThreadStart+0x2f [minkernel\ntdll\rtlstrt.c @ 1153] 
4c 00b7fc48 00000000     ntdll!_RtlUserThreadStart+0x1b [minkernel\ntdll\rtlstrt.c @ 1070]

Just now reading through the stack to see if I can pinpoint what happened.

josalem · 2020-07-27T19:31:32Z

Based on a quick read, it looks like this is happening because System.Diagnostics.Process calls System.Threading.ThreadPool.RegisterWaitForSingleObject which ultimately gets the ThreadPool lock here:

runtime/src/coreclr/src/vm/win32threadpool.cpp

Lines 2244 to 2249 in 168409e

    
           ThreadCB* threadCB; 
        
           { 
        
               CrstHolder csh(&WaitThreadsCriticalSection); 
        
               threadCB = FindWaitThread(); 
        
           }

Then a GC starts after the switch to GCPreemp in frame 0x1c and the GC tries to access the code version lock which causes the violation.

I'm not sure this has anything to do with the test, but rather that gcstress is on and System.Process is used. That seems like it shouldn't be a unique scenario. Let me see if there is a recent-ish change that lead to this.

josalem · 2020-07-27T19:42:08Z

I don't immediately see anything new that might be causing this. The reason that we are getting into this situation it seems is that when I set System.Process.EnableEvents to true in the test harness

runtime/src/tests/tracing/eventpipe/common/IpcUtils.cs

Line 94 in 52d4d8c

process.EnableRaisingEvents = true;

it calls this code:

runtime/src/libraries/System.Diagnostics.Process/src/System/Diagnostics/Process.cs

Lines 643 to 674 in 168409e

    
           /// <devdoc> 
        
           ///    <para> 
        
           ///       Gets or sets whether the <see cref='System.Diagnostics.Process.Exited'/> 
        
           ///       event is fired 
        
           ///       when the process terminates. 
        
           ///    </para> 
        
           /// </devdoc> 
        
           public bool EnableRaisingEvents 
        
           { 
        
               get 
        
               { 
        
                   return _watchForExit; 
        
               } 
        
               set 
        
               { 
        
                   if (value != _watchForExit) 
        
                   { 
        
                       if (Associated) 
        
                       { 
        
                           if (value) 
        
                           { 
        
                               EnsureWatchingForExit(); 
        
                           } 
        
                           else 
        
                           { 
        
                               StopWatchingForExit(); 
        
                           } 
        
                       } 
        
                       _watchForExit = value; 
        
                   } 
        
               } 
        
           }

which is what ultimately registers a wait thread.

I don't think this is an issue with tracing, but rather an overlooked crst ordering problem with the GC and threadpool in System.Process.

Issue: dotnet#38801

VincentBu · 2021-08-04T01:20:10Z

Failed again in runtime 20210803.116

Failed test:

CoreCLR windows x86 Checked no_tiered_compilation @ Windows.10.Amd64.Open

- tracing\\eventpipe\\reverseouter\\reverseouter\\reverseouter.cmd

Error message:

cmdLine:C:\h\w\A25F0977\w\ADC6095F\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.cmd Timed Out (timeout in milliseconds: 600000 from variable __TestTimeout, start: 8/3/2021 10:59:39 PM, end: 8/3/2021 11:09:39 PM)

Return code:      -100
Raw output file:      C:\h\w\A25F0977\w\ADC6095F\uploads\Reports\tracing.eventpipe\reverseouter\reverseouter\reverseouter.output.txt
Raw output:
BEGIN EXECUTION
"C:\h\w\A25F0977\p\corerun.exe"  reverseouter.dll
0.0s: ::== Running test: TEST_ReverseConnectionCanRecycleWhileTracing
0.1s: Server name is 'DOTNET_TRACE_TESTS_wpnolldq.qsa'
0.8s: running sub-process: C:\h\w\A25F0977\p\corerun.exe C:\h\w\A25F0977\w\ADC6095F\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll 0
1.6s: subprocess started: True
1.7s: subprocess PID: 7824
4.0s: Starting EventPipeSession over standard connection
4.1s: Waiting for connection
4.2s: Started EventPipeSession over standard connection with session id: 0x8340de8
4.3s: Got a connection
4.3s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.4s: Got a connection
4.4s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.4s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.4s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.5s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.5s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.5s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.5s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.5s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.5s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.5s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.5s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wpnolldq.qsa
4.5s: { Magic=System.Byte[]; ClrInstanceId=96a3163e-b8c1-4c75-aa63-a5cdf39d9ecd; ProcessId=7824; Unused=0; }
4.5s: Waiting for connection
4.5s: Got a connection
4.5s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_wp


Stack trace
   at tracing_eventpipe._reverseouter_reverseouter_reverseouter_._reverseouter_reverseouter_reverseouter_cmd() in tracing.eventpipe.XUnitWrapper.dll:token 0x600001a+0x284

josalem · 2021-08-04T22:26:53Z

This is a different failure than what this issue is tracking. This looks more similar to #54469.

VincentBu · 2021-09-02T01:23:16Z

Failed again in: runtime-coreclr outerloop 20210901.9

Failed test:

R2R-CG2 windows x86 Checked no_tiered_compilation @ Windows.10.Amd64.Open

- tracing\\eventpipe\\reverseouter\\reverseouter\\reverseouter.cmd

Error message:

Could Not Find C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2\composite-r2r.dll
Could Not Find C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\common.dll.rsp
Could Not Find C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll.rsp

cmdLine:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.cmd Timed Out (timeout in milliseconds: 1800000 from variable __TestTimeout, start: 9/1/2021 11:24:57 PM, end: 9/1/2021 11:54:57 PM)

Return code:      -100
Raw output file:      C:\h\w\C9B20A53\w\B96D0A39\uploads\Reports\tracing.eventpipe\reverseouter\reverseouter\reverseouter.output.txt
Raw output:
BEGIN EXECUTION
common.dll
reverseouter.dll
2 file(s) copied.
Response file: C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\common.dll.rsp
C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2\common.dll
-o:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\common.dll
--targetarch:x86
--verify-type-and-field-layout
-r:C:\h\w\C9B20A53\p\System..dll
-r:C:\h\w\C9B20A53\p\Microsoft..dll
-r:C:\h\w\C9B20A53\p\mscorlib.dll
-r:C:\h\w\C9B20A53\p\netstandard.dll
-O
" "dotnet" "C:\h\w\C9B20A53\p\crossgen2\crossgen2.dll" @"C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\common.dll.rsp"   -r:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2*.dll"
Emitting R2R PE file: C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\common.dll
Response file: C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll.rsp
C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2\reverseouter.dll
-o:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll
--targetarch:x86
--verify-type-and-field-layout
-r:C:\h\w\C9B20A53\p\System..dll
-r:C:\h\w\C9B20A53\p\Microsoft..dll
-r:C:\h\w\C9B20A53\p\mscorlib.dll
-r:C:\h\w\C9B20A53\p\netstandard.dll
-O
" "dotnet" "C:\h\w\C9B20A53\p\crossgen2\crossgen2.dll" @"C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll.rsp"   -r:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2*.dll -r:C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\IL-CG2*.dll"
Emitting R2R PE file: C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll
"C:\h\w\C9B20A53\p\corerun.exe" -p "System.Reflection.Metadata.MetadataUpdater.IsSupported=false" reverseouter.dll
0.0s: ::== Running test: TEST_ReverseConnectionCanRecycleWhileTracing
0.1s: Server name is 'DOTNET_TRACE_TESTS_azr0qmvr.ztt'
0.3s: running sub-process: C:\h\w\C9B20A53\p\corerun.exe C:\h\w\C9B20A53\w\B96D0A39\e\tracing\eventpipe\reverseouter\reverseouter\reverseouter.dll 0
1.2s: subprocess started: True
1.2s: subprocess PID: 2948
1.8s: Starting EventPipeSession over standard connection
1.9s: Waiting for connection
1.9s: Started EventPipeSession over standard connection with session id: 0x3312708
2.0s: Got a connection
2.0s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_azr0qmvr.ztt
2.1s: { Magic=System.Byte[]; ClrInstanceId=a69963bb-4e43-46a5-b430-d113df3e6e56; ProcessId=2948; Unused=0; }
2.1s: Waiting for connection
2.1s: Got a connection
2.1s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_azr0qmvr.ztt
2.1s: { Magic=System.Byte[]; ClrInstanceId=a69963bb-4e43-46a5-b430-d113df3e6e56; ProcessId=2948; Unused=0; }
2.1s: Waiting for connection
2.1s: Got a connection
2.1s: Shutting down Reverse Server at DOTNET_TRACE_TESTS_azr0qmvr.ztt
2.1s: { Magic=System.Byte[]; ClrInstanceId=a69963bb-4e43-46a5-b430-d113df3e6e56; ProcessId=2948; Unused=0; }
2.1s: Waiting for connection
2.1s: Got a connection
2.1s: Sh


Stack trace
   at tracing_eventpipe._reverseouter_reverseouter_reverseouter_._reverseouter_reverseouter_reverseouter_cmd()

josalem · 2021-09-02T17:12:55Z

This is a different failure than what is tracked in this issue. This is an occurrence of #57461

noahfalk · 2022-07-21T08:57:25Z

@kouvel @mangod9 - I came across this while triaging. Kount I think both the code versioning lock and the ThreadpoolWaitThreads lock fall in your area if you can untangle this lock inversion. At first glance it looked like the Process.EnableRaisingEvents part is a red hering and probably any workload that used threadpool in the right way could trigger this.

kouvel · 2022-09-20T17:00:29Z

This should be fixed now in main, the native thread pool has been removed

noahfalk · 2022-09-21T00:05:13Z

Thanks Kount!

v-haren added GCStress area-GC-coreclr labels Jul 6, 2020

Dotnet-GitSync-Bot added the untriaged New issue has not been triaged by the area owner label Jul 6, 2020

mangod9 removed the untriaged New issue has not been triaged by the area owner label Jul 6, 2020

mangod9 added this to the 5.0.0 milestone Jul 6, 2020

BruceForstall added area-Tracing-coreclr and removed area-GC-coreclr labels Jul 6, 2020

BruceForstall assigned josalem Jul 14, 2020

BruceForstall mentioned this issue Jul 20, 2020

Fix fd leak in Diagnostics Server and add better error handling #39129

Merged

briansull mentioned this issue Jul 23, 2020

Implementation of CSE for GT_CNS_INT benefits ARM64 #39096

Merged

BruceForstall added a commit to BruceForstall/runtime that referenced this issue Jul 26, 2020

Disable reverseouter test under GCStress

80dea65

Issue: dotnet#38801

BruceForstall mentioned this issue Jul 26, 2020

Disable reverseouter test under GCStress #39937

Merged

BruceForstall added a commit that referenced this issue Jul 27, 2020

Disable reverseouter test under GCStress (#39937)

042645e

Issue: #38801

josalem added the area-System.Threading label Jul 27, 2020

BruceForstall mentioned this issue Aug 5, 2020

[test] fix hang in macOS variants of reverse diagnostics server tests #40225

Merged

tommcdon modified the milestones: 5.0.0, 6.0.0 Aug 7, 2020

Jacksondr5 pushed a commit to Jacksondr5/runtime that referenced this issue Aug 10, 2020

Disable reverseouter test under GCStress (dotnet#39937)

fe67efd

Issue: dotnet#38801

josalem removed the area-Tracing-coreclr label Nov 7, 2020

josalem removed their assignment Nov 19, 2020

mangod9 modified the milestones: 6.0.0, 7.0.0 Jul 10, 2021

josalem changed the title ~~Test failure: tracing\\eventpipe\\reverseouter\\reverseouter\\reverseouter.cmd~~ Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress Sep 2, 2021

mangod9 added area-Tracing-coreclr and removed area-System.Threading labels Jul 19, 2022

noahfalk added area-runtime and removed area-Tracing-coreclr labels Jul 21, 2022

noahfalk assigned kouvel Jul 21, 2022

jeffschwMSFT added area-VM-coreclr and removed area-runtime labels Jul 21, 2022

mangod9 modified the milestones: 7.0.0, 8.0.0 Jul 27, 2022

kouvel removed their assignment Aug 12, 2022

kouvel added area-TieredCompilation-coreclr and removed area-VM-coreclr labels Aug 12, 2022

kouvel closed this as completed Sep 20, 2022

ghost locked as resolved and limited conversation to collaborators Oct 21, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress #38801

Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress #38801

v-haren commented Jul 6, 2020

ghost commented Jul 6, 2020

BruceForstall commented Jul 6, 2020

josalem commented Jul 27, 2020

BruceForstall commented Jul 27, 2020

josalem commented Jul 27, 2020

josalem commented Jul 27, 2020

josalem commented Jul 27, 2020

VincentBu commented Aug 4, 2021

josalem commented Aug 4, 2021

VincentBu commented Sep 2, 2021

josalem commented Sep 2, 2021

noahfalk commented Jul 21, 2022

kouvel commented Sep 20, 2022

noahfalk commented Sep 21, 2022

Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress #38801

Crst ordering issue between threadpool and Process.EnableRaisingEvents under GCStress #38801

Comments

v-haren commented Jul 6, 2020

ghost commented Jul 6, 2020

BruceForstall commented Jul 6, 2020

josalem commented Jul 27, 2020

BruceForstall commented Jul 27, 2020

josalem commented Jul 27, 2020

josalem commented Jul 27, 2020

josalem commented Jul 27, 2020

VincentBu commented Aug 4, 2021

josalem commented Aug 4, 2021

VincentBu commented Sep 2, 2021

josalem commented Sep 2, 2021

noahfalk commented Jul 21, 2022

kouvel commented Sep 20, 2022

noahfalk commented Sep 21, 2022