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?


Comments (9)

  1. barrkel says:

    The ILGenerator.Emit() call has lots of overloads for the second parameter, including both int32 and int64. The LDC_I8 opcode tries to load an int64, but the C# type of 0 is int32, so the wrong overload is called, and not enough data gets written. If you change the line:

    ilgen.Emit(OpCodes.Ldc_I8, 0);

    to:

    ilgen.Emit(OpCodes.Ldc_I8, (long) 0);

    the program will work as expected.

  2. Yiru's got a great piece up on using SOS to debug code that was emitted using Whidbey's new Lightweight...

  3. yirutang says:

    You are right. 😉

  4. Anonymous says:

    This is excellent information on LCG. Thanks, and keep up the great work!

  5. Yun Jin says:

    Nice post! It's exciting to see use of our new SOS command like DumpIL and DumpArray.

    One comment: to make DumpMD work with decimal value, you could simply prepend "0n" to the number like "0n1541425360". Or, you could even change the debugger engine's default number radix by the command "n 10" ("n 16" will set it back).

  6. yirutang says:

    I would like to save something just for my own record. Here is how our JIT dev would approach to see the LCG x86 code:

    From Shri:

    Here’s what I would do. I have not tried this out, so some steps might need to be twead.

    Write a program with method foo() that throws and catches a dummy exception (for step 3), and then creates and invokes an LCG method

    Compile it and run under windbg

    “sxe clr; g” in windbg to catch the dummy exception with foo() on the stack

    “bp mscorjit!CILJit::compileMethod; g” to get to the JITing of the dynamic method.

    “.loadby sos mscorwks” to load strike

    “!dumpmd poi(poi(@esp+c))” to display the MethodDesc that gets passed to CILJit::compileMethod on the stack.

    “!bpmd poi(poi(@esp+c))” to put a breakpoint in the dynamic method

    “g” to get to the start of the dynamic method

    “!u @eip” to display the x86 code

  7. thanks says:

    Your site is realy very interesting.

  8. Have you ever tried DynamicMethod, one of the coolest features in the .NET 2.0? Hope you have; otherwise,

  9. I mentioned earlier that you can debug Reflection.Emit code . Unfortunately, Ref.Emit code can't be unloaded

Skip to main content