The dead thread reported in ICorProfilerInfo4::EnumThreads

[ww898]

Description

As described in documentation ICorProfilerInfo::ForceGC requires separate native thread for working. The thread will be finished by my profiler during detaching procedure. And I see it in lldb. However, after attaching again to the process the ICorProfilerInfo4::EnumThreads call returns me the already dead thread where ICorProfilerInfo::ForceGC was called sometime ago .

It's the important problem because the thread id can be already reused for a new native thread.

My investigation shows the CoreCLR keeps the static list of managed threads. and only alive threads will be returned in ICorProfilerInfo4::EnumThreads. On the other hand the ICorProfilerInfo::ForceGC adds current thread in this list.

Reproduction Steps

• Create following "hello world" application:

using System;
namespace test { class Program { static void Main(string[] args) {
  Console.WriteLine("Hello World!");
  Console.ReadLine();
}}}

• Publish it as a self contained application and run it in separate console
• Attach and detach a profiler which use ICorProfilerInfo::ForceGC and dump somewhere the thread id after the call.
• Attach lldb and dump the thread list. Check that the thread id is not in the list.
• Attach a profiler which use ICorProfilerInfo4::EnumThreads and see that the dead thread id is in the list of managed threads.

Actual behavior

The native thread id which interesting us is 1BCF69.

The part of the first profiler log;

00000000001BCF69 0 0000000000000000 GCCQ::ForceGcThread
00000000001BCF69 0 0000000000000000 GCCQ::ForceGc // <-- ICorProfilerInfo::ForceGC started
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionStarted gcNumber=0 reason=induced c=5
00000000001BCF69 1 000000014180AA00 GCCQ::OnStarted gcNumber=0 gcState=normal
00000000001BCF69 1 000000014180AA00 MDG2::FlushMetadata
00000000001BCF69 1 000000014180AA00 MDG2::FlushMetadata res=ok
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionStarted gcNumber=0 res=ok
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122F650
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FA50
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FC40
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FCC0
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FD40
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FDC0
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FE48
00000000001BCF69 1 000000014180AA00 MProf::SurvivingReferences2 c=1
00000000001BCF69 1 000000014180AA00 MProf::SurvivingReferences2 c=91
00000000001BCF69 1 000000014180AA00 MProf::RootReferences2 c=42
00000000001BCF69 1 000000014180AA00 BProf::RootReferences c=42
00000000001BCF69 1 000000014180AA00 MProf::ObjectReferences oid=0000000101220048 cid=0000000280E48C80 c=0
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionFinished gcNumber=0
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionFinished gcNumber=0 res=ok
00000000001BCF69 1 000000014180AA00 GCCQ::OnFinished gcNumber=0 gcState=normal
00000000001BCF69 0 0000000000000000 GCCQ::ForceGc res=ok  // <-- ICorProfilerInfo::ForceGC finished
00000000001BCF69 0 0000000000000000 GCCQ::ForceGcThread res=ok

lldb check:

(lldb) thread list
Process 52251 stopped
* thread #1: tid = 0x1bce01, 0x0000000194e1a538 libsystem_kernel.dylib`read + 8, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  thread #2: tid = 0x1bce03, 0x0000000194e19954 libsystem_kernel.dylib`mach_msg_trap + 8
  thread #3: tid = 0x1bce04, 0x0000000194e1f8cc libsystem_kernel.dylib`kevent + 8
  thread #4: tid = 0x1bce05, 0x0000000194e21ad0 libsystem_kernel.dylib`poll + 8
  thread #5: tid = 0x1bce06, 0x0000000194e1a3d4 libsystem_kernel.dylib`__open + 8
  thread #6: tid = 0x1bce07, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #7: tid = 0x1bce08, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #8: tid = 0x1bce0a, 0x0000000194e1a538 libsystem_kernel.dylib`read + 8
  thread #9: tid = 0x1bcf5c, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #10: tid = 0x1bcf5d, 0x0000000194e1b604 libsystem_kernel.dylib`__workq_kernreturn + 8

The part of the second profiler log:

00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete // <--- ICorProfilerCallback3::ProfilerAttachComplete
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000015200C000
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000015200C000 osTid=001BCE01
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C000 osTid=001BCE01 (1822209)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C000 id=00000001
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000015200C600
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000015200C600 osTid=001BCE08
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C600 osTid=001BCE08 (1822216)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C600 id=00000002
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=0000000131808200
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=0000000131808200 osTid=001BCE0A
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=0000000131808200 osTid=001BCE0A (1822218)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=0000000131808200 id=00000003
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000014180AA00 // <--- The dead thread reported here!!!
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000014180AA00 osTid=001BCF69
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000014180AA00 osTid=001BCF69 (1822569)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000014180AA00 id=00000004
00000000001BCE05 1 0000000000000000 ERROR: No such thread

Configuration

I reproduced the issue on macOS:

• Catalina x64: .NET v5.0.402 x64
• Big Sur x64: .NET v5.0.402 x64 / v6.0-rc2 x64
• Monterey arm64: .NET v5.0.402 x64 + Rosetta2 / v6.0-rc2 x64 + Rosetta2 / v6.0-rc2 arm64

The Linux x64/arm64 versions work properly.

I couldn't figure out the best area label to add to this issue. If you have write-permissions please help me learn by adding exactly one area label.

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

Issue Details

---

Description

As described in documentation ICorProfilerInfo::ForceGC requires separate native thread for working. The thread will be finished by my profiler during detaching procedure. And I see it in lldb. However, after attaching again to the process the ICorProfilerInfo4::EnumThreads call returns me the already dead thread where ICorProfilerInfo::ForceGC was called sometime ago .

It's the important problem because the thread id can be already reused for a new native thread.

My investigation shows the CoreCLR keeps the static list of managed threads. and only alive threads will be returned in ICorProfilerInfo4::EnumThreads. On the other hand the ICorProfilerInfo::ForceGC adds current thread in this list.

Reproduction Steps

• Create following "hello world" application:

using System;
namespace test { class Program { static void Main(string[] args) {
  Console.WriteLine("Hello World!");
  Console.ReadLine();
}}}

• Publish it as a self contained application and run it in separate console
• Attach and detach a profiler which use ICorProfilerInfo::ForceGC and dump somewhere the thread id after the call.
• Attach lldb and dump the thread list. Check that the thread id is not in the list.
• Attach a profiler which use ICorProfilerInfo4::EnumThreads and see that the dead thread id is in the list of managed threads.

Actual behavior

The native thread id which interesting us is 1BCF69.

The part of the first profiler log;

00000000001BCF69 0 0000000000000000 GCCQ::ForceGcThread
00000000001BCF69 0 0000000000000000 GCCQ::ForceGc // <-- ICorProfilerInfo::ForceGC started
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionStarted gcNumber=0 reason=induced c=5
00000000001BCF69 1 000000014180AA00 GCCQ::OnStarted gcNumber=0 gcState=normal
00000000001BCF69 1 000000014180AA00 MDG2::FlushMetadata
00000000001BCF69 1 000000014180AA00 MDG2::FlushMetadata res=ok
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionStarted gcNumber=0 res=ok
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122F650
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FA50
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FC40
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FCC0
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FD40
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FDC0
00000000001BCF69 1 000000014180AA00 MProf::FinalizeableObjectQueued f=C oid=000000010122FE48
00000000001BCF69 1 000000014180AA00 MProf::SurvivingReferences2 c=1
00000000001BCF69 1 000000014180AA00 MProf::SurvivingReferences2 c=91
00000000001BCF69 1 000000014180AA00 MProf::RootReferences2 c=42
00000000001BCF69 1 000000014180AA00 BProf::RootReferences c=42
00000000001BCF69 1 000000014180AA00 MProf::ObjectReferences oid=0000000101220048 cid=0000000280E48C80 c=0
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionFinished gcNumber=0
00000000001BCF69 1 000000014180AA00 MProf::GarbageCollectionFinished gcNumber=0 res=ok
00000000001BCF69 1 000000014180AA00 GCCQ::OnFinished gcNumber=0 gcState=normal
00000000001BCF69 0 0000000000000000 GCCQ::ForceGc res=ok  // <-- ICorProfilerInfo::ForceGC finished
00000000001BCF69 0 0000000000000000 GCCQ::ForceGcThread res=ok

lldb check:

(lldb) thread list
Process 52251 stopped
* thread #1: tid = 0x1bce01, 0x0000000194e1a538 libsystem_kernel.dylib`read + 8, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  thread #2: tid = 0x1bce03, 0x0000000194e19954 libsystem_kernel.dylib`mach_msg_trap + 8
  thread #3: tid = 0x1bce04, 0x0000000194e1f8cc libsystem_kernel.dylib`kevent + 8
  thread #4: tid = 0x1bce05, 0x0000000194e21ad0 libsystem_kernel.dylib`poll + 8
  thread #5: tid = 0x1bce06, 0x0000000194e1a3d4 libsystem_kernel.dylib`__open + 8
  thread #6: tid = 0x1bce07, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #7: tid = 0x1bce08, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #8: tid = 0x1bce0a, 0x0000000194e1a538 libsystem_kernel.dylib`read + 8
  thread #9: tid = 0x1bcf5c, 0x0000000194e1d0c0 libsystem_kernel.dylib`__psynch_cvwait + 8
  thread #10: tid = 0x1bcf5d, 0x0000000194e1b604 libsystem_kernel.dylib`__workq_kernreturn + 8

The part of the second profiler log:

00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete // <--- ICorProfilerCallback3::ProfilerAttachComplete
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000015200C000
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000015200C000 osTid=001BCE01
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C000 osTid=001BCE01 (1822209)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C000 id=00000001
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000015200C600
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000015200C600 osTid=001BCE08
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C600 osTid=001BCE08 (1822216)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000015200C600 id=00000002
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=0000000131808200
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=0000000131808200 osTid=001BCE0A
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=0000000131808200 osTid=001BCE0A (1822218)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=0000000131808200 id=00000003
00000000001BCE05 1 0000000000000000 BProf::ProfilerAttachComplete tid=000000014180AA00 // <--- The dead thread reported here!!!
00000000001BCE05 1 0000000000000000 BPPool::DoThreadRecovered tid=000000014180AA00 osTid=001BCF69
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000014180AA00 osTid=001BCF69 (1822569)
00000000001BCE05 1 0000000000000000 BPool::DoThreadRecovered tid=000000014180AA00 id=00000004
00000000001BCE05 1 0000000000000000 ERROR: No such thread

Configuration

I reproduced the issue on macOS Monterey on .NET v5.0 x64 + Rosetta2 / v6.0-rc2 x64 + Rosetta2 / v6.0-rc2 arm64. The Linux x64/arm64 versions work properly.

Author:	ww898
Assignees:	-
Labels:	area-Diagnostics-coreclr, untriaged
Milestone:	-

[tommcdon]

@davmason

[ww898]

I have just reproduced the issue on macOS Catalina/Big Sur x64. Looks like InternalEndCurrentThreadWrapper wasn't called at the end of ICorProfilerInfo::ForceGC thread.

[davmason]

Hi @ww898, thanks for reporting this. Would you be able to create a simplified repro of a profiler that just creates the GC thread and then iterates the threads?

[ww898]

Hi @davmason, Probably I found the root of the problems. It's using pthread_setspecific / pthread_getspecific inside of the pthread key destroy callback.

Register ForceGC thread:

* thread #11, stop reason = breakpoint 1.1
    frame #0: 0x0000000100a0650d libcoreclr.dylib`ThreadStore::AddThread(newThread=0x00007fabe1009600, bRequiresTSL=YES) at threads.cpp:5234:9 [opt]
Target 0: (test) stopped.
(lldb) bt
* thread #11, stop reason = breakpoint 1.1
  * frame #0: 0x0000000100a0650d libcoreclr.dylib`ThreadStore::AddThread(newThread=0x00007fabe1009600, bRequiresTSL=YES) at threads.cpp:5234:9 [opt]
    frame #1: 0x0000000100a05647 libcoreclr.dylib`SetupThread(fInternal=<unavailable>) at threads.cpp:791:5 [opt]
    frame #2: 0x0000000100a0519a libcoreclr.dylib`SetupThreadNoThrow(int*) [inlined] SetupThread() at threads.h:600:12 [opt]
    frame #3: 0x0000000100a05193 libcoreclr.dylib`SetupThreadNoThrow(pHR=0x0000700003ec9db8) at threads.cpp:615 [opt]
    frame #4: 0x0000000100b2f572 libcoreclr.dylib`ETW::GCLog::ForceGCForDiagnostics() at eventtrace.cpp:953:9 [opt]
    frame #5: 0x0000000100aebb32 libcoreclr.dylib`ProfToEEInterfaceImpl::ForceGC(this=<unavailable>) at proftoeeinterfaceimpl.cpp:4641:18 [opt]
    frame #6: 0x00000001033000a6 libJetBrains.Profiler.Core.dylib`jbprof::gc_command_queue::thread_data::force_gc_thread(jb::unique_hld<void*, jb::delete_module_handle, std::__1::integral_constant<void*, (void*)0> >&) + 438
    frame #7: 0x00000001032fe78f libJetBrains.Profiler.Core.dylib`jbprof::gc_command_queue::raw_force_gc_thread(void*) + 143
    frame #8: 0x00007fff6e37c109 libsystem_pthread.dylib`_pthread_start + 148
    frame #9: 0x00007fff6e377b8b libsystem_pthread.dylib`thread_start + 15```

Crash in pthread_getspecific which prevent call DetachThread:

Process 9960 stopped
* thread #11, stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
    frame #0: 0x00007fff6e377bf5 libsystem_pthread.dylib`pthread_getspecific
libsystem_pthread.dylib`pthread_getspecific:
->  0x7fff6e377bf5 <+0>: movq   %gs:(,%rdi,8), %rax
    0x7fff6e377bfe <+9>: retq   

libsystem_pthread.dylib`pthread_setspecific:
    0x7fff6e377bff <+0>: leaq   -0xa(%rdi), %rcx
    0x7fff6e377c03 <+4>: movl   $0x16, %eax
  thread #22, stop reason = breakpoint 4.1
    frame #0: 0x00000001008d45cd libcoreclr.dylib`LOADCallDllMainSafe(module=0x00007fabde60d230, dwReason=2, lpReserved=0x0000000000000000) at module.cpp:1250:18 [opt]
Target 0: (test) stopped.
(lldb) bt
* thread #11, stop reason = EXC_BAD_ACCESS (code=EXC_I386_GPFLT)
  * frame #0: 0x00007fff6e377bf5 libsystem_pthread.dylib`pthread_getspecific
    frame #1: 0x00000001008d4454 libcoreclr.dylib`::LOADCallDllMain(DWORD, LPVOID) [inlined] CorUnix::GetCurrentPalThread() at thread.hpp:684:46 [opt]
    frame #2: 0x00000001008d4444 libcoreclr.dylib`::LOADCallDllMain(DWORD, LPVOID) [inlined] CorUnix::InternalGetCurrentThread() at thread.hpp:689 [opt]
    frame #3: 0x00000001008d4444 libcoreclr.dylib`::LOADCallDllMain(dwReason=3, lpReserved=0x0000000000000000) at module.cpp:1068 [opt]
    frame #4: 0x0000000100900738 libcoreclr.dylib`InternalEndCurrentThreadWrapper(arg=0x00007fabe100ca00) at thread.cpp:167:5 [opt]
    frame #5: 0x00007fff6e37a009 libsystem_pthread.dylib`_pthread_tsd_cleanup + 476
    frame #6: 0x00007fff6e37c512 libsystem_pthread.dylib`_pthread_exit + 70
    frame #7: 0x00007fff6e379e08 libsystem_pthread.dylib`pthread_exit + 42

The thread completely hangs on arm64 wihtout specific reason here:

(lldb) bt                                                                                                             
* thread #20                                                                                                          
  * frame #0: 0x00000001034d6908 libcoreclr.dylib`::LOADCallDllMain(DWORD, LPVOID) [inlined] CorUnix::GetCurrentPalThread() at thread.hpp:684:66 [opt]                                                                                      
    frame #1: 0x00000001034d6908 libcoreclr.dylib`::LOADCallDllMain(DWORD, LPVOID) [inlined] CorUnix::InternalGetCurrentThread() at thread.hpp:689:31 [opt]                                                                                 
    frame #2: 0x00000001034d6908 libcoreclr.dylib`::LOADCallDllMain(dwReason=3, lpReserved=0x0000000000000000) at module.cpp:1076:15 [opt]                                                                                                  
    frame #3: 0x00000001034fd394 libcoreclr.dylib`InternalEndCurrentThreadWrapper(arg=0x000000012580a600) at thread.cpp:172:5 [opt]                                                                                                         
    frame #4: 0x00000001aea0ee14 libsystem_pthread.dylib`_pthread_tsd_cleanup + 448                                   
    frame #5: 0x00000001aea11be0 libsystem_pthread.dylib`_pthread_exit + 84
    frame #6: 0x00000001aea0ebe8 libsystem_pthread.dylib`pthread_exit + 88
    frame #7: 0x00000001aea0eb90 libsystem_pthread.dylib`_pthread_wqthread_exit + 80

[janvorli]

@ww898 thank you a lot for the details! I'll take a look into it. We do something that may be questionable in the InternalEndCurrentThreadWrapper given the fact that it is called from pthread_exit. We call the pthread_setspecific and that might be causing things to break.

[davmason]

@janvorli let me know if this is enough information for you to investigate. I'm happy to help set up a profiler repro if you would like

[janvorli]

@davmason a profiler repro would be nice

[davmason]

Here's a repro: https://github.com/davmason/macos_thread_profiler_repro

All you should have to do is update the path to a coreclr repo here, then ./build.sh and ./repro.sh

[janvorli]

I have tried that locally. While I can see the message "Saw ForceGC thread id in enum list!" printed out, I never got a crash in the LOADCallDllMain like shown above. And looking at how the profiler thread enumeration works, it can easily happen that it returns a thread that doesn't exist anymore. The enumerating loop in ProfilerThreadEnum::Init is called under the thread store lock, but after it returns, threads can exit. Am I missing something?