Test failure: profiler\\rejit\\rejit\\rejit.cmd

[v-haren]

failed in job: runtime-coreclr jitstress 20200424.3

Error message

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.
 at Profiler.Tests.ProfilerTestRunner.LogTestFailure(String error) in F:\workspace\_work\1\s\src\coreclr\tests\src\profiler\common\ProfilerTestRunner.cs:line 135
 at Profiler.Tests.ProfilerTestRunner.Run(String profileePath, String testName, Guid profilerClsid, String profileeArguments, ProfileeOptions profileeOptions) in F:\workspace\_work\1\s\src\coreclr\tests\src\profiler\common\ProfilerTestRunner.cs:line 89
 at Profiler.Tests.RejitWithInlining.Main(String[] args) in F:\workspace\_work\1\s\src\coreclr\tests\src\profiler\rejit\rejit.cs:line 100

Return code: 1
Raw output file: C:\h\w\C01C0A83\w\A45A08F7\e\profiler\rejit\Reports\profiler.rejit\rejit\rejit.output.txt
Raw output:
BEGIN EXECUTION
 "C:\h\w\C01C0A83\p\corerun.exe" rejit.dll 
Profiler path: C:\h\w\C01C0A83\w\A45A08F7\e\profiler\rejit\rejit\Profiler.dll
Disabling tiered compilation.
Profiler path: C:\h\w\C01C0A83\w\A45A08F7\e\profiler\rejit\rejit\Profiler.dll
Profiler.dll!DllGetClassObject
Profiler.dll!Profiler::Initialize

INFO ReJITProfiler::Initialize - Initialize started
Call to GetFunctionFromToken failed with hr=0x80070057
Call to GetFunctionFromToken failed with hr=0x80070057
Call to GetFunctionFromToken failed with hr=0x80070057
Call to GetFunctionFromToken failed with hr=0x80070057
Call to GetFunctionFromToken failed with hr=0x80070057
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=Copy Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=Copy Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=Copy Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=Clear Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=SetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=SetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=SetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=SetValue Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=get_Rank Inlinee=Assert Inlinee module name=C:\h\w\C01C0A83\p\System.Private.CoreLib.dll
INFO ReJITProfiler::AddInlining - Inlining occurred! Inliner=GetLength Inlinee=Assert Inlinee module name=C:\h\w\C0


Stack trace
   at profiler_rejit._rejit_rejit_._rejit_rejit_cmd() in F:\workspace\_work\1\s\artifacts\tests\coreclr\Windows_NT.x86.Checked\TestWrappers\profiler.rejit\profiler.rejit.XUnitWrapper.cs:line 140

[ghost]

Tagging subscribers to this area: @tommcdon
Notify danmosemsft if you want to be subscribed.

[BruceForstall]

This appears to be a problem only for COMPlus_JITMinOpts=1

@dotnet/jit-contrib

[AndyAyersMS]

This is a relatively new test (added in #34411) and I suspect the failure here is not a regression.

Looks like this test is incompatible with COMPlus_JITMinOpts as it expects some inlines to happen when jitting, and min opts supresses all inlining. It would likely fail jitstress for the right stress level, for similar reasons.

We should be able to mark it as optimization sensitive to exclude it from these kinds of tests.

[AndyAyersMS]

It is already marked with <JitOptimizationSensitive>true</JitOptimizationSensitive> but it invokes a subprocess for testing, and that subprocess is the one impacted by minopts.

So need to tweak the test code a bit to pass on this notion to the subprocess.

[erozenfeld]

An alternative solution is to set the environment variables that ensure that inlining is not disabled like I did here:

runtime/src/coreclr/tests/src/JIT/opt/ObjectStackAllocation/ObjectStackAllocationTests.csproj

Lines 17 to 19 in ba8fa9e

	set COMPlus_JITMinOpts=0
	set COMPlus_JitDebuggable=0
	set COMPlus_JitStressModeNamesNot=STRESS_RANDOM_INLINE,STRESS_MIN_OPTS

[AndyAyersMS]

Thanks @erozenfeld -- the test case was already setting some COMPlus vars in code, so I just added a few more.

Fixed via #36420.