Crossgen outerloop regression: ReJIT profiler test does not pass

[kg]

The ReJIT profiler test does not pass on the crossgen outerloop lanes. It's not clear to me whether we should expect this to pass; I don't know much about ReJIT but it seems like it might not be conceptually compatible with what crossgen does. The profiler events seem to be working but something is going wrong with the test.

Unhandled exception. System.Exception: Profiler tests are expected to contain the text 'PROFILER TEST PASSES' in the console output of the profilee app to indicate a passing test. Usually it is printed from the Shutdown() method of the profiler implementation. This text was not found in the output above. Profilee returned exit code 100.
   at Profiler.Tests.ProfilerTestRunner.FailFastWithMessage(String error)
   at Profiler.Tests.ProfilerTestRunner.Run(String profileePath, String testName, Guid profilerClsid, String profileeArguments, ProfileeOptions profileeOptions, Dictionary`2 envVars, String reverseServerName, Boolean loadAsNotification, Int32 notificationCopies)
   at Profiler.Tests.RejitWithInlining.Main(String[] args)

Return code:      1
Raw output file:      C:\h\w\A5E609B0\w\A0EB08E2\uploads\rejit\rejit\output.txt
Raw output:
BEGIN EXECUTION
eventpipe_common.dll
Microsoft.Diagnostics.NETCore.Client.dll
Profiler.dll
profiler_common.dll
rejit.dll
TestLibrary.dll
        6 file(s) copied.
 7:02:43.86
Response file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll.rsp
C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\IL-CG2\*.dll
-o:C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll
--targetarch:x64
--targetos:windows
--verify-type-and-field-layout
--method-layout:random
-r:C:\h\w\A5E609B0\p\System.*.dll
-r:C:\h\w\A5E609B0\p\Microsoft.*.dll
-r:C:\h\w\A5E609B0\p\xunit.*.dll
-r:C:\h\w\A5E609B0\p\mscorlib.dll
-r:C:\h\w\A5E609B0\p\netstandard.dll
"Running CrossGen2:  "C:\h\w\A5E609B0\p\crossgen2\crossgen2.exe" @"C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll.rsp"   --composite  --composite"
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\eventpipe_common.dll
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\Microsoft.Diagnostics.NETCore.Client.dll
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\profiler_common.dll
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\rejit.dll
Emitting R2R PE file: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\TestLibrary.dll
"Running R2RDump:  "dotnet" "C:\h\w\A5E609B0\p\r2rdump\r2rdump.dll" --header --sc --in C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll --out C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\\composite-r2r.dll.r2rdump --val"
 7:02:44.92
 "C:\h\w\A5E609B0\p\corerun.exe" -p "System.Reflection.Metadata.MetadataUpdater.IsSupported=false" -p "System.Runtime.Serialization.EnableUnsafeBinaryFormatterSerialization=true"  rejit.dll 
Profiler path: C:\h\w\A5E609B0\w\A0EB08E2\e\profiler\rejit\rejit\Profiler.dll
Disabling tiered compilation, jitstress, and minopts.
Profilee STDOUT: Profiler.dll!DllGetClassObject
Profilee STDOUT: Profiler.dll!Profiler::Initialize
Profilee STDOUT: **INFO** ReJITProfiler::Initialize - Initialize started
Profilee STDOUT: maxinlining
Profilee STDOUT: TriggerDirectInlining
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - Found function id for target method
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: CallMethodWithoutInlining
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: TriggerInlining
Profilee STDOUT: Inline.InlineeChain1
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - ReJIT Trigger method jitting finished: TriggerReJIT
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - Requesting rejit with inliners for method InlineeTarget
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - ModuleID=7ff898074388 and MethodDef=6000008
Profilee STDOUT: ReJIT should be triggered after this method...
Profilee STDOUT: TriggerDirectInlining
Profilee STDOUT: **INFO** ReJITProfiler::GetReJITParameters - Starting to build IL for method InlineeTarget
Profilee STDOUT: **INFO** ReJITProfiler::GetReJITParameters - Replaced function string with new one.
Profilee STDOUT: **INFO** ReJITProfiler::GetReJITParameters - IL build successful for methodDef=6000008
Profilee STDOUT: **INFO** ReJITProfiler::ReJITCompilationStarted - Saw a ReJIT for function InlineeTarget
Profilee STDOUT: Hello from profiler rejit!
Profilee STDOUT: CallMethodWithoutInlining
Profilee STDOUT: Hello from profiler rejit!
Profilee STDOUT: TriggerInlining
Profilee STDOUT: Inline.InlineeChain1
Profilee STDOUT: Hello from profiler rejit!
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - Revert trigger method jitting finished: TriggerRevert
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - Requesting revert for method InlineeTarget
Profilee STDOUT: **INFO** ReJITProfiler::FunctionSeen - ModuleID=7ff898074388 and MethodDef=6000008
Profilee STDOUT: Revert should be triggered after this method...
Profilee STDOUT: TriggerDirectInlining
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: CallMethodWithoutInlining
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: TriggerInlining
Profilee STDOUT: Inline.InlineeChain1
Profilee STDOUT: Inline.InlineeTarget
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=get_IsSupported Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=OnProcessExit Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=Enter Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=GetEnumerator Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=get_Current Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=get_Value Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=TryGetTarget Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=RaiseUnloadEvent Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=OnProcessExit Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=ThrowLockTakenException Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetEnumerator Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGetTarget Inlinee=get_Target Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=get_Target Inlinee=GetTarget Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetTarget Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetTarget Inlinee=get_Target Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=get_IsSupported Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=get_EventListenersLock Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Enter Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=GetEnumerator Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=MoveNext Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=get_Current Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=TryGetTarget Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Add Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=get_EventListenersLock Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=IsEntered Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=GetEnumerator Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=MoveNext Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=get_Current Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=DisposeOnShutdown Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=.ctor Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=ThrowLockTakenException Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetEnumerator Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGetTarget Inlinee=get_Target Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=get_Target Inlinee=GetTarget Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetTarget Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetTarget Inlinee=get_Target Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=MoveNext Inlinee=MoveNextRare Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=MoveNextRare Inlinee=ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=IsEntered Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetEnumerator Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=SuppressFinalize Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=SuppressFinalize Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=MoveNext Inlinee=MoveNextRare Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=MoveNextRare Inlinee=ThrowInvalidOperationException_InvalidOperation_EnumFailedVersion Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=StelemRef_Helper Inlinee=TryGet Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=StelemRef_Helper Inlinee=StelemRef_Helper_NoCacheLookup Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGet Inlinee=TableData Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGet Inlinee=KeyToBucket Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGet Inlinee=Element Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TryGet Inlinee=TableMask Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=TableData Inlinee=GetRawData Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=KeyToBucket Inlinee=HashShift Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=StelemRef_Helper_NoCacheLookup Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=StelemRef_Helper_NoCacheLookup Inlinee=ThrowArrayMismatchException Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=get_IsSupported Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=get_EventListenersLock Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=IsEntered Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=Dispose Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=IsEntered Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=SuppressFinalize Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=SuppressFinalize Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=SuppressFinalize Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=SuppressFinalize Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=get_EventListenersLock Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=Enter Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=get_EventListenersLock Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=IsEntered Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Dispose Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Enter Inlinee=ThrowLockTakenException Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=IsEntered Inlinee=ThrowIfNull Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfNull Inlinee=Throw Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Disable Inlinee=Disable Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Unregister Inlinee=get_IsAllocated Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Unregister Inlinee=Free Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=ThrowIfInvalid Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=GetHandleValue Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=InternalFree Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfInvalid Inlinee=ThrowInvalidOperationException_HandleIsNotInitialized Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetHandleValue Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Unregister Inlinee=get_IsAllocated Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Unregister Inlinee=Free Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=ThrowIfInvalid Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=GetHandleValue Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=Free Inlinee=InternalFree Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=ThrowIfInvalid Inlinee=ThrowInvalidOperationException_HandleIsNotInitialized Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: **INFO** ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetHandleValue Inlinee=.ctor Inlinee module name=C:\h\w\A5E609B0\p\System.Private.CoreLib.dll
Profilee STDOUT: Profiler.dll!Profiler::Shutdown
Profilee STDOUT: **INFO** ReJITProfiler::Shutdown -  rejit count=1 expected rejit count=ffffffff
Profilee STDOUT: **FAIL** ReJITProfiler::Shutdown - Test failed number of failures=0
Test failed: Profiler tests are expected to contain the text 'PROFILER TEST PASSES' in the console output of the profilee app to indicate a passing test. Usually it is printed from the Shutdown() method of the profiler implementation. This text was not found in the output above. Profilee returned exit code 100.
Expected: 100
Actual: -532462766
END EXECUTION - FAILED
FAILED

[kg]

Notes about rejit and crossgen from David Mason on discord:

ReJIT is a concept in the ICorProfiler interface, and it's a little confusingly named versus tiered compilation. ReJIT is talking about the ability of an ICorProfiler (C++ library that can hook in to extension points in the runtime) to be able to arbitrarily rewrite the IL of a method. The intended case is for APM stuff like AppInsights, etc, to be able to inject instrumentation in methods to keep track of http calls, exceptions thrown, whatever
In the desktop days the way we did ReJIT was incompatible with NGEN images so profilers had to block the whole image or at least the methods they cared about from loading (there are APIs for that too) and force them to jit normally so they could participate
In the modern runtime and R2R images you can ReJIT methods that are already loaded via R2R
Let me know if you want more details on any specific area
PS if anyone from the jit team is talking about rejit they almost always mean tiered compilation

EDIT: The issue may be related to how some of the crossgen lanes have tiered compilation turned off.

[kg]

In this test, InlineeTarget is not being inlined when it's expected to. The expected rejit count is -1 because it wasn't inlined.

[kg]

CompositeBuildMode=1 causes this to pass (EDIT: Intermittently 🤷‍♀️), with a rejit count of 3. CompositeBuildMode=0 makes it fail.

[kg]

This passes on latest main for me in both regular and composite build modes.

[kg]

Looks like it only fails on linux and OSX.

[kg]

This is actually broken on Windows too but in a way that doesn't make the test fail. Relevant Windows output:

1> Hello from profiler rejit!
1> **INFO** ReJITProfiler::FunctionSeen - Revert trigger method jitting finished: TriggerRevert
1> **INFO** ReJITProfiler::FunctionSeen - Requesting revert for method InlineeTarget
1> **INFO** ReJITProfiler::FunctionSeen - ModuleID=7ff96e062940 and MethodDef=6000008
1> Revert should be triggered after this method...
1> Hello from profiler rejit!
1> Inline.InlineeTarget
1> CallMethodWithoutInlining
1> Inline.InlineeTarget
1> Hello from profiler rejit!
1> Hello from profiler rejit!
1> Inline.InlineeTarget

Comparable output from an OSX lane (that failed):

1> Hello from profiler rejit!
1> **INFO** FunctionSeen - Revert trigger method jitting finished: TriggerRevert
1> **INFO** FunctionSeen - Requesting revert for method InlineeTarget
1> **INFO** FunctionSeen - ModuleID=10e6e68f0 and MethodDef=6000008
1> Revert should be triggered after this method...
1> TriggerDirectInlining
1> Inline.InlineeTarget
1> CallMethodWithoutInlining
1> Inline.InlineeTarget
1> TriggerInlining
1> Inline.InlineeChain1
1> Inline.InlineeTarget

It doesn't look like the revert actually works at all on Windows!

I believe the reason that the OSX and Linux lanes are failing may be that for some reason more BCL code is being jitted on-the-fly than is jitted on my Windows configuration. If I compare the inlining history in the stdout, my local Windows run doesn't inline much at startup while the OSX run inlines a bunch of BCL code before reaching the 'maxinlining' message:

Windows

Profiler path: Z:\runtime\artifacts\tests\coreclr\windows.x64.Checked\profiler\rejit\rejit\Profiler.dll
Disabling tiered compilation, jitstress, and minopts.
1> Profiler.dll!DllGetClassObject
1> Profiler.dll!Profiler::Initialize
1> **INFO** ReJITProfiler::Initialize - Initialize started
1> maxinlining

OSX

Profiler path: ~/working/w/A54F0933/e/profiler/rejit/rejit/libProfiler.dylib
Disabling tiered compilation, jitstress, and minopts.
1> Profiler.dll!DllGetClassObject
1> Profiler.dll!Profiler::Initialize
1> **INFO** Initialize - Initialize started
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=get_Cache Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=get_GenericCache Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=CompareExchange<System.__Canon> Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=.ctor Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=CompareExchange<System.__Canon> Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CreateAndCache Inlinee=CompareExchange<System.__Canon> Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=get_Cache Inlinee=Assert Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=Assert Inlinee=Assert Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange<System.__Canon> Inlinee=CompareExchange Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange Inlinee=ThrowNullReferenceException Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=.ctor Inlinee=.ctor Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange<System.__Canon> Inlinee=CompareExchange Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange Inlinee=ThrowNullReferenceException Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange<System.__Canon> Inlinee=CompareExchange Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> **INFO** AddInlining - Inlining occurred! Inliner=CompareExchange Inlinee=ThrowNullReferenceException Inlinee module name=~/working/p/System.Private.CoreLib.dll
1> maxinlining

The actual flow after this point is different too, inlining simply isn't happening on the OSX run in places where it happens on Windows and it seems like it's intended for it to happen in those places. Whether that means the optimizer is deciding not to inline for some platform specific reason, or some other problem is happening, I'm not sure.

On windows I'm also seeing this error in the output:

1> Call to GetFunctionFromToken failed with E_INVALIDARG, this may be caused by the method not yet being loaded
1> **INFO** ReJITProfiler::JITCachedFunctionSearchFinished - Inlining occurred, but name could not be resolved! Inliner=ModuleId=Z:\runtime\artifacts\tests\coreclr\windows.x64.Checked\profiler\rejit\rejit\rejit.dll Token=600000d,  Inlinee=InlineeTarget Inlinee module name=Z:\runtime\artifacts\tests\coreclr\windows.x64.Checked\profiler\rejit\rejit\rejit.dll
1> Call to GetFunctionFromToken failed with E_INVALIDARG, this may be caused by the method not yet being loaded
1> **INFO** ReJITProfiler::JITCachedFunctionSearchFinished - Inlining occurred, but name could not be resolved! Inliner=ModuleId=Z:\runtime\artifacts\tests\coreclr\windows.x64.Checked\profiler\rejit\rejit\rejit.dll Token=600000e,  Inlinee=InlineeTarget Inlinee module name=Z:\runtime\artifacts\tests\coreclr\windows.x64.Checked\profiler\rejit\rejit\rejit.dll

I would personally prefer that this kind of failure make the test not pass, but maybe it's expected? The message doesn't make it sound expected.

[kg]

Should be fixed by #117826