Debugging LCG
Maybe it is a little to early to jump into this talk but I think for a user starting to use LCG, he will hit this problem in the first place. When you are emitting a dynamic method and doesn't have a way to persist it, you can imagine that it could be hard to debug. But SoS has some build-in support for LCG that works surprisingly well (Thanks to Michael Stanton(our SOS dev lead) and Dario Russi(who created LCG)).
Let me start with a program that caused LCG to throw:
using System.Reflection;
using System.Reflection.Emit;
using System;
public class Test
{
public static void Main()
{
DynamicMethod dm = new DynamicMethod("dm", typeof(Int64), new Type[]{}, typeof(Test).Module);
ILGenerator ilgen = dm.GetILGenerator();
ilgen.EmitWriteLine("Insdie DM");
ilgen.Emit(OpCodes.Ldc_I8, 0);
ilgen.Emit(OpCodes.Ret);
dm.CreateDelegate(typeof(D)).DynamicInvoke(null);
}
}
delegate Int64 D();
When excuting the program, we throw:
Unhandled Exception: System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> System.InvalidProgramException: Common Language Runtime detected an invalid program.
at dm()
at D.Invoke()
--- End of inner exception stack trace ---
at System.RuntimeMethodHandle._InvokeMethodFast(Object target, Object[] arguments, SignatureStruct& sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner)
at System.RuntimeMethodHandle.InvokeMethodFast(Object target, Object[] arguments, Signature sig, MethodAttributes methodAttributes, RuntimeTypeHandle typeOwner) in c:\vbl\ndp\clr\src\BCL\System\RuntimeHandles.cs:line 686
at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture, Boolean skipVisibilityChecks) in c:\vbl\ndp\clr\src\BCL\System\Reflection\XXXInfos.cs:line 1472
at System.Delegate.DynamicInvokeImpl(Object[] args) in c:\vbl\ndp\clr\src\BCL\System\Delegate.cs:line 102
at System.Delegate.DynamicInvoke(Object[] args) in c:\vbl\ndp\clr\src\BCL\System\Delegate.cs:line 94
at Test.Main()
Welcome to the LCG world. :-) How could we debug this issue?
Let's start "windbg repro.exe" and let it stop at CLR exceptions by typing in "sxe clr". (I will usually type in "sxe eh" as well just as a habbit).
It will stop at the place it is throwing and the call stack looks like this:
0:000> kb
ChildEBP RetAddr Args to Child
0012ba94 5b15cfc9 0012bcac 5b0fc1a6 00000727 mscorjit!debugError+0xc8 [c:\vbl\ndp\clr\src\jit\il\error.cpp @ 113]
0012beac 5b16488d 5b0fc8d8 5b0fca20 00000009 mscorjit!badCode3+0x69 [c:\vbl\ndp\clr\src\jit\il\error.cpp @ 219]
0012bf08 5b1660c1 00217031 00000006 0022774c mscorjit!Compiler::fgFindJumpTargets+0x51bd [c:\vbl\ndp\clr\src\jit\il\flowgraph.cpp @ 1834]
0012bfa0 5b1598d2 0012d558 0012d520 00162a80 mscorjit!Compiler::fgFindBasicBlocks+0x81 [c:\vbl\ndp\clr\src\jit\il\flowgraph.cpp @ 2418]
0012c034 5b15ac98 02e21b49 0012cfbc 0012c700 mscorjit!Compiler::compCompile+0x702 [c:\vbl\ndp\clr\src\jit\il\compiler.cpp @ 2376]
0012c0e0 5b15be5b 0012cfbc 0012c700 0012c128 mscorjit!jitNativeCode+0x178 [c:\vbl\ndp\clr\src\jit\il\compiler.cpp @ 2845]
0012c13c 5dd01521 5b249ed4 0012cfbc 0012c700 mscorjit!CILJit::compileMethod+0xbb [c:\vbl\ndp\clr\src\jit\il\ee_il_dll.cpp @ 212]
0012c1f0 5dd0185d 0020e548 0012cfbc 0012c700 mscorwks!invokeCompileMethodHelper+0x101 [c:\vbl\ndp\clr\src\vm\jitinterface.cpp @ 9763]
0012c2e8 5dd01adb 0020e548 0012cfbc 0012c700 mscorwks!invokeCompileMethod+0x17d [c:\vbl\ndp\clr\src\vm\jitinterface.cpp @ 9791]
0012c354 5dd0288e 0020e548 0012cfbc 0012c700 mscorwks!CallCompileMethodWithSEHWrapper+0x1db [c:\vbl\ndp\clr\src\vm\jitinterface.cpp @ 9881]
0012d144 5dfb0042 02e21430 00000000 00107410 mscorwks!UnsafeJitFunction+0x5de [c:\vbl\ndp\clr\src\vm\jitinterface.cpp @ 10289]
0012d234 5dfb2b12 00000000 00000000 0012d558 mscorwks!MethodDesc::MakeJitWorker+0x362 [c:\vbl\ndp\clr\src\vm\prestub.cpp @ 437]
0012d3e0 5dfb1726 00000000 0012d558 0012d520 mscorwks!MethodDesc::DoPrestub+0xdd2 [c:\vbl\ndp\clr\src\vm\prestub.cpp @ 1447]
0012d4f0 00391f0a 0012d520 12345678 5e58f190 mscorwks!PreStubWorker+0x326 [c:\vbl\ndp\clr\src\vm\prestub.cpp @ 906]
WARNING: Frame IP not in any known module. Following frames may be wrong.
0012d508 00ba0256 00000000 0012d558 00162a80 0x391f0a
0012d540 5d86cf0d 0012e648 00bc46e4 00bc46e4 CLRStub[StubLinkStub]@ba0256
0012d570 5da1710d 0012db30 00000000 0012db00 mscorwks!CallDescrWorkerInternal+0x33 [c:\vbl\ndp\clr\src\vm\i386\asmhelpers.asm @ 930]
0012d9a4 5da16e07 0012db30 00000000 0012db00 mscorwks!CallDescrWorker+0x10d [c:\vbl\ndp\clr\src\vm\class.cpp @ 13529]
0012dae4 5dd0e6ad 0012db30 00000000 0012db00 mscorwks!CallDescrWorkerWithHandler+0x2b7 [c:\vbl\ndp\clr\src\vm\class.cpp @ 13436]
0012def4 5dd0d93a 02e22534 0012e22c 0012e0f0 mscorwks!MethodDesc::CallDescr+0xd1d [c:\vbl\ndp\clr\src\vm\method.cpp @ 2288]
We can see that JIT is throwing because we emitted some invalid IL.
The first argument for UnsafeJitFunction is the Dynamic Method's MethodDesc.
if we do:
0:000> .loadby sos mscorwks
0:000> !dumpmd 02e21430
Method Name: DynamicClass.dm()
Class: 02e21288
MethodTable: 02e212f8
mdToken: 06000000
Module: 0020e0b0
IsJitted: no
m_CodeOrIL: ffffffff
We can see the Method signature and the method name of the method. Moreover, if we do
0:000> !dumpil 02e21430
This is dynamic IL. Exception info is not reported at this time.
If a token is unresolved, run "!do <addr>" on the addr given
in parenthesis. You can also look at the token table yourself, by
running "!DumpArray 00bc4644".
IL_0000: ldstr 70000002 "Insdie DM"
IL_0005: call 6000003 System.Console.WriteLine(System.String)
IL_000a: ldc.i8 0
We can see the IL of the method body. Well, this method has some problem so the IL body is not complete.
If we do dumparray, you can find the scope table!
0:000> !DumpArray 00bc4644
Name: System.Object[]
MethodTable: 5bcb9434
EEClass: 5bcb9a14
Size: 32(0x20) bytes
Array: Rank 1, Number of elements 4, Type CLASS
Element Methodtable: 5bca30dc
[0] null
[1] 00bc42b8
[2] 00bc3eb0
[3] 00bc72b8
LCG has its own token table to handles and strings so this table is very important. From the IL body, we know that the string should live in the [2] position of the token table. We can verify it by doing:
0:000> !do 00bc3eb0
Name: System.String
MethodTable: 5bca3760
EEClass: 5bca36f0
Size: 36(0x24) bytes
(C:\WINDOWS\Microsoft.NET\Framework\v2.0.50523dbg\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
String: Insdie DM
Fields:
MT Field Offset Type VT Attr Value Name
5bca76f4 4000095 4 System.Int32 0 instance 10 m_arrayLength
5bca76f4 4000096 8 System.Int32 0 instance 9 m_stringLength
5bca511c 4000097 c System.Char 0 instance 49 m_firstChar
5bca3760 4000098 10 System.String 0 shared static Empty
>> Domain:Value 0015d8f8:5bc567a4 <<
5bcb98d0 4000099 14 System.Char[] 0 shared static WhitespaceChars
>> Domain:Value 0015d8f8:00bc12c8 <<
The Console.WriteLine's method handle should be in [3] so:
0:000> !do 00bc72b8
Name: System.RuntimeMethodHandle
MethodTable: 5bcadfcc
EEClass: 5bd7a614
Size: 12(0xc) bytes
(C:\WINDOWS\Microsoft.NET\Framework\v2.0.50523dbg\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
MT Field Offset Type VT Attr Value Name
5bca6cbc 40004df 4 System.IntPtr 0 instance 1541425360 m_ptr
0:000> !dumpmd 0n1541425360
Method Name: System.Console.WriteLine(System.String)
Class: 5bd75708
MethodTable: 5bca66f0
mdToken: 06000767
Module: 5bc44000
IsJitted: yes
m_CodeOrIL: 5b704610
The two most common errors that caused InvalidProgramException are:
1. You are emitting bad IL; 2. If you are using open scope API, you could be messing up token tables.
So these Sos commands should help you to identify most of the InvalidProgramExceptions.
I will explain these open scope APIs, token scope in my later posts.
Another easy way to check you IL stream is to emit the same IL stream using Reflection.Emit so that you can bake the method and use tools such as peverify to identify where you did wrong.
Finally, can you tell me where I did wrong in this small program?