none
Invalid IL program detected in Event Log - .Net Profiler RRS feed

  • Question

  • I am injecting the entry and exit function call ILs into the .Net code from my profiler. 

    The signature of the function that i inject is 

    COR_SIGNATURE sigFunctionProbe4[] = {
    		IMAGE_CEE_CS_CALLCONV_DEFAULT,      // default calling convention
    		0x03,                               
    		ELEMENT_TYPE_VOID,                  
    		ELEMENT_TYPE_U8,                    
    		ELEMENT_TYPE_I4,                    
    		ELEMENT_TYPE_I4,
    	};

    and the corresponding function's definition in the helper assembly is 

    public static void EnterFunction(UInt64 fID, int flag1, int flag2)
    {
    ..
    ..
    }

    The application that i am profiling is "Citrix Director" . In this case when my profiler gets attached to the application  , the application does not even log in and throws an error in EventLog ("the w3wp.exe process is not crashed") as attached in the image 

    But if i Add en extra argument in the signature of the method , then everything works fine - The highly confusing part. 

    Works Fine with the following 

    COR_SIGNATURE sigFunctionProbe4[] = {
    		IMAGE_CEE_CS_CALLCONV_DEFAULT,      // default calling convention
    		0x04,                               
    		ELEMENT_TYPE_VOID,                  
    		ELEMENT_TYPE_U8,                    
    		ELEMENT_TYPE_I4,                    
    		ELEMENT_TYPE_I4,
    		ELEMENT_TYPE_I4,
    	};

    public static void EnterFunction(UInt64 fID, int flag1, int flag2, int flag3)
    {
    ..
    ..
    }

    Should i inject an helper function call with four arguments only..? (this happens only for profiling few applications - for many other web applications profiler works flawlessly)

    Wednesday, August 3, 2016 10:05 AM

Answers

  • I'm not sure where you are getting those max-stack values from, the max-stack is a 16 bit value at an offset of 2. so the max-stack values are actually 2,4,65528,65530 respectfully. In each case the working version had a max-stack value of 2 more than the non-working version, but I don't think that's where the problem lies.

    Aside from the max-stack, the only difference between the working and non-working versions is the addition of the i4 argument. (as I'm sure you expected)

    Just to confirm, when you add the MemberRef record to the module, do you track the new metadata tokens per module or are you using the same pair of metadata values for all jitted methods regardless of module.

    • Marked as answer by Selva VS Monday, August 8, 2016 9:48 AM
    Friday, August 5, 2016 10:29 AM
  • I guess , i had solved this issue. 

    Here is the solution,

    Please open this https://github.com/jimschubert/clr-profiler/blob/master/src/ILRewrite10Source/ILRewriteProfiler/ilrewriter.cpp

    In the above file Line number 390 .. The CEE_SWITCH_ARG is being assigned to opcode which is in enum Line number 80.

    Later from line number 395 "InsertBefore(...)" function .. The maxstack value is being incremented by accessing the integer array "k_rgnStackPushes[]" using the opcode CEE_SWITCh_ARG.. 

    But I noticed that CEE_SWITCH_ARG is not defined in that array. So it is returning value "32762" (it's range).

    I defined it now.. And now it is perfect.. :) :) :)  But still i have a doubt whether the value of CEE_SWITCH_ARG should be "1" or "0" in that integer array.

    The stack behavior of CEE_SWITCH is Push0.. which is defined as 0. So i guess it should be the same for CEE_SWITCH_ARG




    • Edited by Selva VS Monday, August 8, 2016 7:43 AM
    • Marked as answer by Selva VS Monday, August 8, 2016 9:48 AM
    Monday, August 8, 2016 7:33 AM

All replies

  • Sounds like there is an issue with the IL being injected to call your helper method. I would suggest verifying the resulting IL of the last few methods jitted before the exception.

    One way to do this is to have a debug version of your profiler that writes to a log file whenever it:

    • jits a method (include the generated method body bytes) or
    • throws an InvalidProgramException.

    (it would probably be a good idea to include thread ID and timestamp in the log entries)

    Then when you get this error, go to the exception log entry and work your way back, verifying each method body and any metadata tokens it uses until you find the offending method.

    Wednesday, August 3, 2016 10:01 PM
  • I am very near to the solution. I sorted out which function throws the invalid code error. 

    In ICORProfilerInfo->SetILFunctionBody(...) i pass the LPBYTES  function body. How can i print that into readable IL codes.?

    HRESULT SetILFunctionBody(unsigned size, LPBYTE pBody)
    	{
    			
    	IfFailRet(m_pICorProfilerInfo->SetILFunctionBody(m_moduleId, m_tkMethod, pBody));
    
    		return S_OK;
    	}
    Thursday, August 4, 2016 10:23 AM
  • Visual Studio has a bunch of "Memory" windows available from the `Debug > Windows > Memory` menu (or Ctrl+Alt+M, 1), you can use them to read arbitrary regions of the debuggee's virtual address space as a sequence of hex values. I used to decode the bytes into IL by hand, but then many moons ago, I decided to throw a simple program together to do it for me :)
    Thursday, August 4, 2016 11:04 AM
  • I put this print code above SetILFunctionBody .. and i got the hex values as below,

    FILE* fp; fp = fopen ("C:\\Temp\\myfile.txt" , "w"); for(int j = 0; j < size; j++) { fprintf(fp,"%02X", pBody[j]); fprintf(fp,"\n"); } fprintf(fp,"\n\n\n"); fclose(fp);

    corprofilerInfo->SetILFunctionBody(mid,token1,pBody);

    13 30 02 00 B2 00 00 00 3D 15 00 11 21 F0 3F 9C 94 FA 7F 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1D 2B 00 0A 02 28 EC 00 00 06 02 7B 6B 00 00 04 0A 06 45 06 00 00 00 02 00 00 00 14 00 00 00 55 00 00 00 55 00 00 00 26 00 00 00 38 00 00 00 2B 48 02 28 F4 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 02 28 F4 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 02 28 CB 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 02 28 CC 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 72 F6 92 00 70 28 C8 00 00 0A 7A 00 21 F0 3F 9C 94 FA 7F 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1E 2B 00 0A 2A 00 00

    Just want to make sure that, is this the right place to print before going into decoding.


    Thursday, August 4, 2016 11:36 AM
  • .maxstack 2
    .locals 1100153D
      ldc.i8          140714211819504
      ldc.i4          226
      ldc.i4          226
      call            0A002B1D
      ldarg.0
      call            060000EC
      ldarg.0
      ldfld           0400006B
      stloc.0
      ldloc.0
      switch          { IL_0045 IL_0057 IL_0098 IL_0098 IL_0069 IL_007B }
      br.s            IL_008D
    
    IL_0045  
      ldarg.0
      call            060000F4
      ldsfld          0A0000C6
      ldarg.0
      call            06002BAE
      throw
    
    IL_0057  
      ldarg.0
      call            060000F4
      ldsfld          0A0000C6
      ldarg.0
      call            06002BAE
      throw
    
    IL_0069  
      ldarg.0
      call            060000CB
      ldsfld          0A0000C6
      ldarg.0
      call            06002BAE
      throw
    
    IL_007B  
      ldarg.0
      call            060000CC
      ldsfld          0A0000C6
      ldarg.0
      call            06002BAE
      throw
    
    IL_008D  
      ldstr           700092F6
      call            0A0000C8
      throw
    
    IL_0098  
      nop
      ldc.i8          140714211819504
      ldc.i4          226
      ldc.i4          226
      call            0A002B1E
      ret
    

    I don't see anything obviously wrong with the instructions ... assuming that:

    • You only inserted the first 4 instructions and the last 4 before the ret
    • The unmodified instructions were correct.
    • And the two inserted calls both have the first signature you listed in your opening post,

    You might want to double-check the metadata tokens (0A002B1D, 0A002B1E) are what you expect (keeping in mind that they are module specific).


    Actually, the maxstack is 2 but your additions require 3 ... I'm not sure it's enforced, but might be worth checking out.
    Thursday, August 4, 2016 12:30 PM
  • "You might want to double-check the metadata tokens (0A002B1D, 0A002B1E) are what you expect (keeping in mind that they are module specific)."

    If i understood what u mean correctly -  Those functions are not module specific , I define the member reference  in all the modules that gets loaded. 

    The problematic function is ThrowIfClosedOrNotOpen and ThrowIfClosedOrOpened . If i skip injecting from these two functions then the application gets loaded perfectly. 

    And,

    Can i know using which tool you had converted to IL ? 


    • Edited by Selva VS Thursday, August 4, 2016 12:54 PM
    Thursday, August 4, 2016 12:52 PM
  • All metadata tokens are module specific, you will need to define a MemberRef in each module that needs it (and each module may end up with a different token for the same target member - be sure to use the one for the specific module that defines the method to be instrumented).

    I decoded the IL using a tool I wrote almost a year ago ... I never really got it to a state worthy of publishing :), I just modify it as the need arises.

    Thursday, August 4, 2016 1:07 PM
  • If i have four arguments in the injected method then "there is no Invalid code detected by CLR" and the hex values of the IL are

    13 30 04 00 BC 00 00 00 3D 15 00 11 21 F0 3F 9B 94 FA 7F 00
    00 20 E2 00 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1D 2B 00 
    0A 02 28 EC 00 00 06 02 7B 6B 00 00 04 0A 06 45 06 00 00 00 
    02 00 00 00 14 00 00 00 55 00 00 00 55 00 00 00 26 00 00 00 
    38 00 00 00 2B 48 02 28 F4 00 00 06 7E C6 00 00 0A 02 28 AE 
    2B 00 06 7A 02 28 F4 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 
    06 7A 02 28 CB 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 
    02 28 CC 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 72 F6 
    92 00 70 28 C8 00 00 0A 7A 00 21 F0 3F 9B 94 FA 7F 00 00 20 
    E2 00 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1E 2B 00 0A 2A 

    .. what is the difference between this hex values and the previous one..?

    The max stack value of this method being assigned in header is 196612. and for the previous IL is 196610

    The IL Code for another problematic function mentioned previously (with three arguments - invalid code) :

    13 30 F8 FF 8E 00 00 00 3D 15 00 11 21 18 38 9A 94 FA 7F 00 
    00 20 E2 00 00 00 20 E2 00 00 00 28 1D 2B 00 0A 02 28 EC 00 
    00 06 02 7B 6B 00 00 04 0A 06 45 06 00 00 00 31 00 00 00 31 
    00 00 00 31 00 00 00 31 00 00 00 02 00 00 00 14 00 00 00 2B 
    24 02 28 CB 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 02 
    28 CC 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 06 7A 72 C8 90 
    00 70 28 C8 00 00 0A 7A 00 21 18 38 9A 94 FA 7F 00 00 20 E2 
    00 00 00 20 E2 00 00 00 28 1E 2B 00 0A 2A 00 00

    with Four Arguments (this works)

    13 30 FA FF 98 00 00 00 3D 15 00 11 21 88 3F 9B 94 FA 7F 00 
    00 20 E2 00 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1D 2B 00 
    0A 02 28 EC 00 00 06 02 7B 6B 00 00 04 0A 06 45 06 00 00 00 
    31 00 00 00 31 00 00 00 31 00 00 00 31 00 00 00 02 00 00 00 
    14 00 00 00 2B 24 02 28 CB 00 00 06 7E C6 00 00 0A 02 28 AE 
    2B 00 06 7A 02 28 CC 00 00 06 7E C6 00 00 0A 02 28 AE 2B 00 
    06 7A 72 C8 90 00 70 28 C8 00 00 0A 7A 00 21 88 3F 9B 94 FA 
    7F 00 00 20 E2 00 00 00 20 E2 00 00 00 20 E2 00 00 00 28 1E 
    2B 00 0A 2A 

    Hopefully with your help in comparing these ILs the issue should be found out..!! :-)


    • Edited by Selva VS Friday, August 5, 2016 7:37 AM
    Friday, August 5, 2016 6:48 AM
  • I'm not sure where you are getting those max-stack values from, the max-stack is a 16 bit value at an offset of 2. so the max-stack values are actually 2,4,65528,65530 respectfully. In each case the working version had a max-stack value of 2 more than the non-working version, but I don't think that's where the problem lies.

    Aside from the max-stack, the only difference between the working and non-working versions is the addition of the i4 argument. (as I'm sure you expected)

    Just to confirm, when you add the MemberRef record to the module, do you track the new metadata tokens per module or are you using the same pair of metadata values for all jitted methods regardless of module.

    • Marked as answer by Selva VS Monday, August 8, 2016 9:48 AM
    Friday, August 5, 2016 10:29 AM
  • Those member refs are entry/exit function calls (to find the time taken of functions). The metadata tokens will be the same for all the modules .

    I add the member refs using DefineMemberRef in IMetaDataEmit for all the modules that gets loaded. 

    Friday, August 5, 2016 10:43 AM
  • That sounds like it might be the problem.

    Lest say you want to instrument MethodA in ModuleA and MethodB in ModuleB such that they both call MethodC in ModuleC. You will need to add a MemberRef to both ModuleA and ModuleB, but they won't necessarily get the same metadata token. If you try to use the token you got from adding it to ModuleA when instrumenting MethodB, you run the risk of referencing a completely unrelated member or using an outright invalid token.

    Remember, the metadata token is essentially just a tuple of table id and record number, and each module has it's own set of tables.

    Friday, August 5, 2016 11:25 AM
  • In each module i am defining the Member reference of the Enter/Exit functions. And forgot to tell that , i have separate objects for each modules that gets loaded . Inside that structure object I have the metadata tokens of that module. 

    And during JITcompilation, i take  the mdToken from the Module's structure object and inject it. So each modules will have it's own metadata token for those two helper member references. (Sorry previously i am wrong).

    If i am having the same mdtoken for all the modules , then i would have got "invalid code exception" if i have 4  arguments in the signature. :(

    I am referring to the max-stack value which is in line number 688 from the code below. 

    https://github.com/jimschubert/clr-profiler/blob/master/src/ILRewrite10Source/ILRewriteProfiler/ilrewriter.cpp

    • Edited by Selva VS Friday, August 5, 2016 11:47 AM
    Friday, August 5, 2016 11:42 AM

  • If i am having the same mdtoken for all the modules , then i would have got "invalid code exception" if i have 4  arguments in the signature. :(

    Not necessarily, you could get unlucky and have landed on a another method that happened to have the same signature ... but that's just splitting hairs :)

    I am referring to the max-stack value which is in line number 688 from the code below. 

    https://github.com/jimschubert/clr-profiler/blob/master/src/ILRewrite10Source/ILRewriteProfiler/ilrewriter.cpp

    That's not what I meant, in an earlier post you mentioned that the first pair of methods had a max-stack of 196610 and 196612, I wasn't sure where you got those values from (these values are too big to fit in the 16-bit field and the bytes you provided indicated a max-stack of 2 and 4 respectfully.

    If we look at the second pair, with a max stack of only 65528 and 65530. These values seem very excessive to me, I would struggle to justify even a small fraction of that.

    Saturday, August 6, 2016 12:44 AM
  • I guess , i had solved this issue. 

    Here is the solution,

    Please open this https://github.com/jimschubert/clr-profiler/blob/master/src/ILRewrite10Source/ILRewriteProfiler/ilrewriter.cpp

    In the above file Line number 390 .. The CEE_SWITCH_ARG is being assigned to opcode which is in enum Line number 80.

    Later from line number 395 "InsertBefore(...)" function .. The maxstack value is being incremented by accessing the integer array "k_rgnStackPushes[]" using the opcode CEE_SWITCh_ARG.. 

    But I noticed that CEE_SWITCH_ARG is not defined in that array. So it is returning value "32762" (it's range).

    I defined it now.. And now it is perfect.. :) :) :)  But still i have a doubt whether the value of CEE_SWITCH_ARG should be "1" or "0" in that integer array.

    The stack behavior of CEE_SWITCH is Push0.. which is defined as 0. So i guess it should be the same for CEE_SWITCH_ARG




    • Edited by Selva VS Monday, August 8, 2016 7:43 AM
    • Marked as answer by Selva VS Monday, August 8, 2016 9:48 AM
    Monday, August 8, 2016 7:33 AM
  • If CEE_SWITCH_ARG is a pseudo instruction representing a single destination offset (and I suspect it is) then it should not have any effect on the stack depth (other than copying it to the target offset like other branching instructions). CEE_SWITCH however would decrement the stack depth by 1.

    Consider the following example, the comments indicate the stack depth upon completion of the instruction. The max-stack for this method will be 3

      ldarg.1                      // 1
      ldarg.2                      // 2
      switch IL_A, IL_B, IL_C      // 1
      br IL_DEF                    // 1
    
    IL_A:
      ldc.3                        // 2
      br IL_END                    // 2
    
    IL_B:
      ldc.4                        // 2
      br IL_END                    // 2
    
    IL_C:
      ldarg.3                      // 2
      ldc.5                        // 3
      add                          // 2
      br IL_END                    // 2
    
    IL_DEF:
      ldc.0                        // 2
    
    IL_END:
      add                          // 1
      ret



    Monday, August 8, 2016 9:24 AM
  • Thanks Brian.. Your replies helped a lot
    Monday, August 8, 2016 10:26 AM