libraries-jitstress failure in System.Diagnostics.Tests.StackFrameTests.Ctor_FNeedFileInfo #69154
Comments
|
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. |
jakobbotsch
added
the
area-CodeGen-coreclr
|
Tagging subscribers to this area: @JulieLeeMSFT Issue DetailsSeen on testing for #69117. C:\h\w\BB8A09D2\w\AA4A094A\e>set COMPlus
COMPlus_JitStress=1
COMPlus_TieredCompilation=0
C:\h\w\BB8A09D2\w\AA4A094A\e>call RunTests.cmd --runtime-path C:\h\w\BB8A09D2\p
----- start Tue 05/10/2022 15:49:12.15 =============== To repro directly: =====================================================
pushd C:\h\w\BB8A09D2\w\AA4A094A\e\
"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
C:\h\w\BB8A09D2\w\AA4A094A\e>"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.StackTrace.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.StackTrace.Tests (found 53 test cases)
Starting: System.Diagnostics.StackTrace.Tests (parallel test collections = on, max threads = 4)
System.Diagnostics.Tests.StackFrameTests.Ctor_FNeedFileInfo(fNeedFileInfo: False) [FAIL]
Expected GetILOffset() -1 for InvokeStub_StackFrameTests.Ctor_FNeedFileInfo at offset 44 in file:line:column <filename unknown>:0:0
to be greater or equal to zero.
Expected: True
Actual: False
Stack Trace:
/_/src/libraries/System.Diagnostics.StackTrace/tests/StackFrameTests.cs(171,0): at System.Diagnostics.Tests.StackFrameTests.VerifyStackFrameSkipFrames(StackFrame stackFrame, Boolean isFileConstructor, Int32 skipFrames, MethodInfo expectedMethod, Boolean isCurrentFrame)
at InvokeStub_StackFrameTests.Ctor_FNeedFileInfo(Object, Object, IntPtr*)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(60,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Finished: System.Diagnostics.StackTrace.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.StackTrace.Tests Total: 121, Errors: 0, Failed: 1, Skipped: 0, Time: 10.512s
|
jakobbotsch
added
area-VM-coreclr
and removed
area-CodeGen-coreclr
|
@steveharter this does not repro if I revert 5195418. cc @dotnet/jit-contrib |
jakobbotsch
added
JitStress
Right, if you want to depend on certain frames showing up in stack traces make sure those frames involve |
VincentBu
added
arch-arm64
os-linux
|
Failed again in: runtime-coreclr libraries-jitstress 20220510.1 Failed test: Error message: or |
|
Tagging subscribers to this area: @tommcdon Issue DetailsSeen on testing for #69117. C:\h\w\BB8A09D2\w\AA4A094A\e>set COMPlus
COMPlus_JitStress=1
COMPlus_TieredCompilation=0
C:\h\w\BB8A09D2\w\AA4A094A\e>call RunTests.cmd --runtime-path C:\h\w\BB8A09D2\p
----- start Tue 05/10/2022 15:49:12.15 =============== To repro directly: =====================================================
pushd C:\h\w\BB8A09D2\w\AA4A094A\e\
"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
C:\h\w\BB8A09D2\w\AA4A094A\e>"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.StackTrace.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.StackTrace.Tests (found 53 test cases)
Starting: System.Diagnostics.StackTrace.Tests (parallel test collections = on, max threads = 4)
System.Diagnostics.Tests.StackFrameTests.Ctor_FNeedFileInfo(fNeedFileInfo: False) [FAIL]
Expected GetILOffset() -1 for InvokeStub_StackFrameTests.Ctor_FNeedFileInfo at offset 44 in file:line:column <filename unknown>:0:0
to be greater or equal to zero.
Expected: True
Actual: False
Stack Trace:
/_/src/libraries/System.Diagnostics.StackTrace/tests/StackFrameTests.cs(171,0): at System.Diagnostics.Tests.StackFrameTests.VerifyStackFrameSkipFrames(StackFrame stackFrame, Boolean isFileConstructor, Int32 skipFrames, MethodInfo expectedMethod, Boolean isCurrentFrame)
at InvokeStub_StackFrameTests.Ctor_FNeedFileInfo(Object, Object, IntPtr*)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(60,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Finished: System.Diagnostics.StackTrace.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.StackTrace.Tests Total: 121, Errors: 0, Failed: 1, Skipped: 0, Time: 10.512s
|
|
Tagging subscribers to this area: @dotnet/area-system-reflection Issue DetailsSeen on testing for #69117. C:\h\w\BB8A09D2\w\AA4A094A\e>set COMPlus
COMPlus_JitStress=1
COMPlus_TieredCompilation=0
C:\h\w\BB8A09D2\w\AA4A094A\e>call RunTests.cmd --runtime-path C:\h\w\BB8A09D2\p
----- start Tue 05/10/2022 15:49:12.15 =============== To repro directly: =====================================================
pushd C:\h\w\BB8A09D2\w\AA4A094A\e\
"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
popd
===========================================================================================================
C:\h\w\BB8A09D2\w\AA4A094A\e>"C:\h\w\BB8A09D2\p\dotnet.exe" exec --runtimeconfig System.Diagnostics.StackTrace.Tests.runtimeconfig.json --depsfile System.Diagnostics.StackTrace.Tests.deps.json xunit.console.dll System.Diagnostics.StackTrace.Tests.dll -xml testResults.xml -nologo -nocolor -notrait category=IgnoreForCI -notrait category=OuterLoop -notrait category=failing
Discovering: System.Diagnostics.StackTrace.Tests (method display = ClassAndMethod, method display options = None)
Discovered: System.Diagnostics.StackTrace.Tests (found 53 test cases)
Starting: System.Diagnostics.StackTrace.Tests (parallel test collections = on, max threads = 4)
System.Diagnostics.Tests.StackFrameTests.Ctor_FNeedFileInfo(fNeedFileInfo: False) [FAIL]
Expected GetILOffset() -1 for InvokeStub_StackFrameTests.Ctor_FNeedFileInfo at offset 44 in file:line:column <filename unknown>:0:0
to be greater or equal to zero.
Expected: True
Actual: False
Stack Trace:
/_/src/libraries/System.Diagnostics.StackTrace/tests/StackFrameTests.cs(171,0): at System.Diagnostics.Tests.StackFrameTests.VerifyStackFrameSkipFrames(StackFrame stackFrame, Boolean isFileConstructor, Int32 skipFrames, MethodInfo expectedMethod, Boolean isCurrentFrame)
at InvokeStub_StackFrameTests.Ctor_FNeedFileInfo(Object, Object, IntPtr*)
/_/src/libraries/System.Private.CoreLib/src/System/Reflection/MethodInvoker.cs(60,0): at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
Finished: System.Diagnostics.StackTrace.Tests
=== TEST EXECUTION SUMMARY ===
System.Diagnostics.StackTrace.Tests Total: 121, Errors: 0, Failed: 1, Skipped: 0, Time: 10.512s
|
|
@steveharter The reflection invoke PR was reverted in 69373. Please make sure that this and other known stacktrace related issues are addressed before resubmitting. |
Those tests with Also the test failures with |
The JIT is free to inline the actual method invoked into the reflection-created DynamicMethod given how things are setup today. If we want to see the actual method invoked on the stack, we should call it using a function pointer. Calling the actual method invoked using a function pointer would also allow us to reuse the invokers between different methods with the same signature. |
My understanding is that DynamicMethods are never inlined but has been considered. FWIW here's a small repro. It fails in a Debug build of the runtime + using System.Reflection;
using System.Reflection.Emit;
namespace ConsoleApp
{
internal class Program
{
static void Main(string[] args)
{
MethodInfo mi = typeof(Foo).GetMethod(nameof(Foo.CallMe), BindingFlags.Public | BindingFlags.Static)!;
Action action = CreateInvokeDelegate(mi);
try
{
action();
}
catch (Exception e)
{
Console.WriteLine(e.ToString());
Console.WriteLine("Call stack contains CallMe():" + e.ToString().Contains("CallMe()")); // should be True
}
}
static Action CreateInvokeDelegate(MethodInfo method)
{
var dm = new DynamicMethod(
"InvokeStub",
returnType: null,
parameterTypes: null,
restrictedSkipVisibility: true);
ILGenerator il = dm.GetILGenerator();
il.Emit(OpCodes.Call, method);
il.Emit(OpCodes.Ret);
return (Action)dm.CreateDelegate(typeof(Action), target: null);
}
}
public class Foo
{
public static void CallMe()
{
throw new Exception("Here");
}
}
} |
That's correct. However, other (non-dynamic) methods can be inlined into dynamic methods. It is what's happening here. |
|
Thanks I didn't catch the meaning of the "into the reflection-created DynamicMethod" |
|
Yes using -il.Emit(OpCodes.Call, method);
+il.Emit(OpCodes.Ldftn, method);
+il.EmitCalli(OpCodes.Calli, CallingConventions.Standard, null, null, null);I'll work on doing this along with a hashtable to re-use the invokers. |
If the plan is to reuse the invoke stubs then I assume in the final implementation the function pointer will be more opaque to the JIT? |
I was wondering if using
The way I see it is that static void Main(string[] args)
{
MethodInfo mi = typeof(Foo).GetMethod(nameof(Foo.CallMe), BindingFlags.Public | BindingFlags.Static)!;
IntPtr methodPtr = mi.MethodHandle.GetFunctionPointer();
Action<IntPtr> action = CreateInvokeDelegate(mi);
try
{
action(methodPtr);
}
catch (Exception e)
{
Console.WriteLine(e.ToString());
Console.WriteLine("Call stack contains CallMe():" + e.ToString().Contains("CallMe()")); // should be True
}
}
static Action<IntPtr> CreateInvokeDelegate(MethodInfo method)
{
var dm = new DynamicMethod(
"InvokeStub",
returnType: null,
parameterTypes: new Type[] { typeof(IntPtr) },
restrictedSkipVisibility: true);
ILGenerator il = dm.GetILGenerator();
il.Emit(OpCodes.Ldarg_0);
il.EmitCalli(OpCodes.Calli, CallingConventions.Standard, typeof(void), Type.EmptyTypes, null);
il.Emit(OpCodes.Ret);
return (Action<IntPtr>)dm.CreateDelegate(typeof(Action<IntPtr>), target: null);
} |
Yes, this should be fine. The only problem I can think of is guarded devirtualization, but we do not ever expect to get PGO data for dynamic methods.
We also have the |
|
Fixed by #69575 |
ghost
locked as resolved and limited conversation to collaborators
Seen on testing for #69117.
Pipeline: https://dev.azure.com/dnceng/public/_build/results?buildId=1762407&view=results
Test: https://dev.azure.com/dnceng/public/_build/results?buildId=1762407&view=ms.vss-test-web.build-test-results-tab&runId=47434070&resultId=110968&paneView=debug
Log: https://helixre8s23ayyeko0k025g8.blob.core.windows.net/dotnet-runtime-refs-pull-69117-merge-a31de8e595db4aa8af/System.Diagnostics.StackTrace.Tests/1/console.b93af7d3.log?helixlogtype=result
The text was updated successfully, but these errors were encountered: