Loading a Raw Profiler with an Instrumentation Method DLL causes Access Violation during process teardown phase on pwsh.exe

CLRInstrumentationEngine/src/InstrumentationEngine/ProfilerManager.h の SendEventToRawProfilerCallback と ProfilerManager.cpp の JITCompilationFinished から始め、次に pwsh.exe、NaglerInstrumentationMethod、Microsoft.RawProfilerHook_x64.dll を使って teardown を再現します。提供された dump と callback スタックを使用して unload race を追跡します。完了の条件は、プロセスの teardown がアンロード済みの Raw Profiler へディスパッチせず、STATUS_ACCESS_VIOLATION で終了もしないことです。

I've observed this issue with a custom written Instrumentation Method loaded along with a Raw Profiler. But the same issue exists if we use NaglerInstrumentationMethod along with Microsoft.RawProfilerHook_x64.dll (both provided on the CLR IE repo). From my observation, during process teardown phase, CLR IE unloads the Raw Profiler from the main thread. The main thread then comes out of apphost!wmain and goes on to call ExitProcess. But in between, the main thread gets swapped out and a profiler callback (JITCompilationFinished / ReJITCompilationFinished as per observation) arrives from a different pwsh.exe worker thread to the CLR IE, causing it to invoke the Raw Profiler callback, which then AVs due to it already been unloaded. This causes the process to exit with a STATUS_ACCESS_VIOLATION return code even though there is no issue with the user code being run.

The dump taken at the point of Access Violation shows the Raw Profiler has been unloaded:

0:011> lmu m Micro*
Unloaded modules:
00007ffd`7a890000 00007ffd`7aa70000   Microsoft.RawProfilerHook_x64.d    // The RawProfiler compiled from the CLR IE provided example

The Access Violation happens in a pwsh.exe worker thread:

0:009> .exr -1
ExceptionAddress: 00007ffbb5c163f6 (MicrosoftInstrumentationEngine_x64!ATL::CComPtrBase<ICorProfilerCallback>::CComPtrBase<ICorProfilerCallback>+0x0000000000000046)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 0000000000000000
   Parameter[1]: 00007ffbb6fb8230
Attempt to read from address 00007ffbb6fb8230

0:009> k
 # Child-SP          RetAddr               Call Site
00 000000a7`4da7e9a0 00007ffb`b5c1565a     MicrosoftInstrumentationEngine_x64!ATL::CComPtrBase<ICorProfilerCallback>::CComPtrBase<ICorProfilerCallback>+0x46 [C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.44.35207\atlmfc\include\atlcomcli.h @ 194] 
01 000000a7`4da7e9e0 00007ffb`b5c1e89a     MicrosoftInstrumentationEngine_x64!ATL::CComPtr<ICorProfilerCallback>::CComPtr<ICorProfilerCallback>+0x2a [C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.44.35207\atlmfc\include\atlcomcli.h @ 349] 
02 000000a7`4da7ea10 00007ffb`b5c0a0f5     MicrosoftInstrumentationEngine_x64!ATL::CComPtr<ICorProfilerCallback>::operator=+0x3a [C:\Program Files\Microsoft Visual Studio\2022\Professional\VC\Tools\MSVC\14.44.35207\atlmfc\include\atlcomcli.h @ 360] 
03 000000a7`4da7ea60 00007ffb`b5bf5a74     MicrosoftInstrumentationEngine_x64!MicrosoftInstrumentationEngine::CProfilerManager::SendEventToRawProfilerCallback<ICorProfilerCallback,long,unsigned __int64,long,int>+0xa5 [C:\work\Github\CLRIE\CLRInstrumentationEngine\src\InstrumentationEngine\ProfilerManager.h @ 385] 
04 000000a7`4da7eaf0 00007ffb`b7283a61     MicrosoftInstrumentationEngine_x64!MicrosoftInstrumentationEngine::CProfilerManager::JITCompilationFinished+0x1b4 [C:\work\Github\CLRIE\CLRInstrumentationEngine\src\InstrumentationEngine\ProfilerManager.cpp @ 1954] 
05 000000a7`4da7ebd0 00007ffb`b725a6d8     coreclr!EEToProfInterfaceImpl::JITCompilationFinished+0x79 [D:\a\_work\1\s\src\coreclr\vm\eetoprofinterfaceimpl.cpp @ 3158] 
06 000000a7`4da7ec20 00007ffb`b71b79e5     coreclr!ProfControlBlock::DoProfilerCallbackHelper<int (__cdecl*)(ProfilerInfo *),long (__cdecl*)(EEToProfInterfaceImpl *,unsigned __int64,long,int),unsigned __int64,long,int>+0x40 [D:\a\_work\1\s\src\coreclr\inc\profilepriv.h @ 284] 
07 (Inline Function) --------`--------     coreclr!ProfControlBlock::DoOneProfilerIteration+0x50 [D:\a\_work\1\s\src\coreclr\inc\profilepriv.h @ 199] 
08 (Inline Function) --------`--------     coreclr!ProfControlBlock::IterateProfilers+0x50 [D:\a\_work\1\s\src\coreclr\inc\profilepriv.h @ 207] 
09 (Inline Function) --------`--------     coreclr!ProfControlBlock::DoProfilerCallback+0x50 [D:\a\_work\1\s\src\coreclr\inc\profilepriv.h @ 295] 
0a (Inline Function) --------`--------     coreclr!ProfControlBlock::JITCompilationFinished+0x50 [D:\a\_work\1\s\src\coreclr\inc\profilepriv.inl @ 411] 
0b 000000a7`4da7ec60 00007ffb`b7050177     coreclr!MethodDesc::JitCompileCodeLockedEventWrapper+0x1676ed [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 882] 
0c 000000a7`4da7ed80 00007ffb`b70df9da     coreclr!MethodDesc::JitCompileCode+0x2d7 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 707] 
0d (Inline Function) --------`--------     coreclr!MethodDesc::PrepareILBasedCode+0x153 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 433] 
0e (Inline Function) --------`--------     coreclr!MethodDesc::PrepareCode+0x153 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 321] 
0f 000000a7`4da7ee20 00007ffb`b70dee91     coreclr!CodeVersionManager::PublishVersionableCodeIfNecessary+0x27a [D:\a\_work\1\s\src\coreclr\vm\codeversion.cpp @ 1734] 
10 000000a7`4da7f220 00007ffb`b70dec28     coreclr!MethodDesc::DoPrestub+0x131 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 2597] 
11 000000a7`4da7f300 00007ffb`b717d9a5     coreclr!PreStubWorker+0x218 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp @ 2424] 
12 000000a7`4da7f400 00007ffb`b1dff264     coreclr!ThePreStub+0x55 [D:\a\_work\1\s\src\coreclr\vm\amd64\ThePreStubAMD64.asm @ 21] 

The managed stack shows this is a pwsh.exe worker thread:

0:009> .loadby sos coreclr
0:009> !clrstack
OS Thread Id: 0xc7c (9)
        Child SP               IP Call Site
000000A74DA7F378 00007ffbb5c163f6 [PrestubMethodFrame: 000000a74da7f378] System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1[[System.Int32, System.Private.CoreLib]].SetException(System.Exception)
000000A74DA7F4B0 00007ffbb1dff264 System.IO.Pipes.PipeStream+ConnectionValueTaskSource.CompleteCore(UInt32, UInt32) [/_/src/libraries/System.IO.Pipes/src/System/IO/Pipes/PipeStream.ValueTaskSource.cs @ 235]
000000A74DA7F500 00007ffbb4e464bd System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ExecutionContext.cs @ 179]
000000A74DA7F570 00007ffbb4e5b210 System.Threading.PortableThreadPool+IOCompletionPoller+Callback.Invoke(Event) [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.IO.Windows.cs @ 265]
000000A74DA7F640 00007ffbb502a521 System.Threading.ThreadPoolTypedWorkItemQueue`2[[System.Threading.PortableThreadPool+IOCompletionPoller+Event, System.Private.CoreLib],[System.Threading.PortableThreadPool+IOCompletionPoller+Callback, System.Private.CoreLib]].System.Threading.IThreadPoolWorkItem.Execute() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs @ 1204]
000000A74DA7F6C0 00007ffbb4e4f5c4 System.Threading.ThreadPoolWorkQueue.Dispatch() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/ThreadPoolWorkQueue.cs @ 989]
000000A74DA7F750 00007ffbb4e5c463 System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart() [/_/src/libraries/System.Private.CoreLib/src/System/Threading/PortableThreadPool.WorkerThread.NonBrowser.cs @ 102]
000000A74DA7FA80 00007ffbb717c663 [DebuggerU2MCatchHandlerFrame: 000000a74da7fa80] 

The main thread which had unloaded the Raw Profiler and was on its way to call ExitProcess, but was swapped out in between:

0:010> ~0k
 # Child-SP          RetAddr               Call Site
00 000000a7`4cb7f328 00007ffc`005fc436     ntdll!NtOpenKeyEx+0x14
01 000000a7`4cb7f330 00007ffc`0068547c     KERNELBASE!Wow64NtOpenKey+0x86
02 000000a7`4cb7f3d0 00007ffc`005fc38d     KERNELBASE!BaseRegOpenKeyInternal+0x100
03 000000a7`4cb7f4c0 00007ffc`005fba21     KERNELBASE!LocalBaseRegOpenKey+0x1d
04 000000a7`4cb7f510 00007ffc`005fb8c9     KERNELBASE!RegOpenKeyExInternalW+0x141
05 000000a7`4cb7f5b0 00007ffb`dbc87295     KERNELBASE!RegOpenKeyExW+0x19
06 000000a7`4cb7f5f0 00007ffb`dbc712f1     mscoree!FindLatestVersionWithCallback+0x99
07 000000a7`4cb7f6e0 00007ffb`dbc71560     mscoree!InitShimImpl+0xcd
08 000000a7`4cb7f980 00007ffb`dbc77468     mscoree!GetShimImpl+0x18
09 000000a7`4cb7f9b0 00007ffc`00526d93     mscoree!ShellShim_CorExitProcess+0x18
0a 000000a7`4cb7f9e0 00007ffc`004f05b4     ucrtbase!try_cor_exit_process+0x367cf
0b 000000a7`4cb7fa10 00007ffc`004f045f     ucrtbase!exit_or_terminate_process+0x3c
0c 000000a7`4cb7fa40 00007ff6`7c38122f     ucrtbase!common_exit+0x6f
0d 000000a7`4cb7fa90 00007ffc`02b77374     apphost!__scrt_common_main_seh+0x173 [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 295] 
0e 000000a7`4cb7fad0 00007ffc`02cfcc91     KERNEL32!BaseThreadInitThunk+0x14
0f 000000a7`4cb7fb00 00000000`00000000     ntdll!RtlUserThreadStart+0x21

I have the full process dump available if anyone wants to take a deeper look at this.