none
.Net Profiler in Windows 2016 - Error in Profiled Web Application RRS feed

  • Question

  • Hi,

    My .Net instrumentation Profiler has a C++ code and a helper assembly which is added in GAC using gacutil.exe. 

    It works perfectly well in the OS till 2012 and windows 8.1. But while profiling the same web application in Windows 2016 OS, it throws an error (But the application dint Crash ,i.e . the w3wp.exe dint close).

    1. First request after the iisreset throws 

    Initial Error after iisreset

    2. Then on Giving a refresh (F5) , the error comes as. - Still the w3wp.exe pid is same.

    Second error

    3. On refreshing the third time the application opens up. 

    But without my profiler the application opens up on the first request itself. Injecting on some 'X' function throws the error , i guess. Cant able to finalize the reason for the issue. 

    Regards,

    ./Selva

    Friday, June 3, 2016 4:41 AM

Answers

  • If it were me debugging this, my top priority would be to identify which function is triggering the exception (the function with invalid code, I'm fairly sure that the exception is thrown by the jit or pre-jit verification. Either way the method will not be on the stack so you will probably need to check which was the last method jitted before the exception). My second step would then be to get the raw bytes passed to SetILFunctionBody for that method and decompile them, to see if it looks sane.

    2. I changed the 6 bytes to 9 bytes and still it dint work out. 


    To be honest, I wasn't expecting that to be the cause, these instructions are relatively uncommon and the average size is probably less than 6 anyway (unless switches get involved, but that doesn't matter if you are treating each jump target as its own pseudo-instruction).

    I did not update any separate exception handler table - which i should do for sure - Can i get some sample codes and links to learn about that in detail?

    I don't have any examples for you on this, I can only direct you to ECMA-335 Partition II Section 25.4 (and 25.4.6 in particular). Basically the method body consists of a method header, followed by IL and then the data sections (I'm sure you are already familiar with the first two by now), the exception handler table will be in one of the data sections.

    But for now , To capture the intermediate functions when exception is thrown I call the Exit call logging function from "ExceptionSearchFunctionEnter" call back

    I'm not entirely sure what you mean, if you mean that you are using ExceptionSearchFunctionEnter to detect when a method exits via an exception, then you should use ExceptionUnwindFinallyEnter instead as ExceptionSearchFunctionEnter means something else and will give misleading information, particularly when you encounter exception filters that call other methods (which will become more common now that C#6 has introduced support for them.)

    Kindly check the ilrewrite.cpp from that project i linked above . Is that correct ? or should i consider any other opcodes additionally as the method exit ?

    It sounds like you already have a plan for leaving a function due to exceptions. ret is probably the only instruction you need ... except for one complication - the tail call. The 'tailcall.' prefix opcode can appear before a 'call' or 'callvirt' instruction as a hint to use the tail call optimization (remove the current frame on the call stack just before calling the target method), such calls must be immediately followed by a ret instruction and so inserting your logic between the call and the ret can cause problems.

    Note: If you are instrumenting 'only' to call a helper method with the FunctionID (and stuff that can be statically determined from it's metadata) then you might want to look into using the ELT hooks instead of instrumenting. They are easier to use, but won't work if you need to call back into managed code (eg. accessing a property on an argument).


    • Edited by Brian Reichle Thursday, June 9, 2016 11:14 AM
    • Marked as answer by Selva VS Thursday, June 9, 2016 12:02 PM
    Thursday, June 9, 2016 11:10 AM
  • My guess would be that you generated invalid IL/Exception handlers somewhere. The invalid method was not DefaultErrorBarTypeValue but was triggered by it (direct call, static constructor, critical region dependency, inlined into one of these things, ...)

    I would suggest looking at the last few methods instrumented before the error and verifying that the IL is valid and consistent with any applicable exception handlers (it's probably the last method instrumented on that thread but I haven't done enough research to t say for certain).



    Saturday, June 4, 2016 1:30 AM

All replies

  • My guess would be that you generated invalid IL/Exception handlers somewhere. The invalid method was not DefaultErrorBarTypeValue but was triggered by it (direct call, static constructor, critical region dependency, inlined into one of these things, ...)

    I would suggest looking at the last few methods instrumented before the error and verifying that the IL is valid and consistent with any applicable exception handlers (it's probably the last method instrumented on that thread but I haven't done enough research to t say for certain).



    Saturday, June 4, 2016 1:30 AM
  • I don't have any invalid method there(as it works in all other Operating system except Windows 2016). And i have got a clue while debugging with different possible tries.

    1. The entry and exit helper functions that i inject is having 2 arguments.

    EnterLoggings(UInt64,int)
    {
    }
    
    ExitLoggings(UInt64,int)
    {
    }

    When i reduce the number of argument in the Exit or Entry Log function. Eg. If i make ExitLoggings(Uint64,int) as ExitLoggings(UInt64) . Then the error is not coming.

    Only if i have two arguments in both the above two functions( two arguments can be same or different) , then the application throws that "Invalid program detected " error. Whereas i need to use two arguments only in the helper functions. I cant reduce the number of arguments. 

    What could be the reason for this? How to proceed with this


    • Edited by Selva VS Monday, June 6, 2016 10:21 AM
    Monday, June 6, 2016 10:20 AM
  • Does Windows 2016 have the same version of the framework as the other operating systems you tested against? Are you instrumenting framework/run-time dlls or just your own?

    When you reduced the number of arguments and found that it worked, I assume you changed the way the code was instrumented to compensate, did you push fewer things onto the evaluation stack or insert a 'pop' instruction just before the call instruction? What did you remove? Where do the values come from?

    InvalidProgramException indicates strongly that the run-time found something wrong with a method, but there is no guarantee that all versions of the run-time are equally vigilant. It is also possible that a change in the implementation of a framework assembly caused a previously missed bug to be hit.

    Were you able to identify the specific method that the run-time deemed to be invalid? If so, check to see if it has the same signature/IL on your Windows 2016 machine as on your other machines.

    Monday, June 6, 2016 1:00 PM
  • This is the code (from CLR Profiler) which exports the changed IL into the function's body. 

    	// One instruction produces 6 bytes in the worst case
    		unsigned maxSize = m_nInstrs * 6;
    
    		
    		m_pOutputBuffer = new BYTE[maxSize];
    		IfNullRet(m_pOutputBuffer);
    
    again:
    		BYTE * pIL = m_pOutputBuffer;
    
    		bool fBranch = false;
    		unsigned offset = 0;
    
    		// Go over all instructions and produce code for them
    		for (ILInstr * pInstr = m_IL.m_pNext; pInstr != &m_IL; pInstr = pInstr->m_pNext)
    		{
    			pInstr->m_offset = offset;
    
    			unsigned opcode = pInstr->m_opcode;
    			if (opcode < CEE_COUNT)
    			{
    				// CEE_PREFIX1 refers not to instruction prefixes (like tail.), but to
    				// the lead byte of multi-byte opcodes. For now, the only lead byte
    				// supported is CEE_PREFIX1 = 0xFE.
    				if (opcode >= 0x100)
    					m_pOutputBuffer[offset++] = CEE_PREFIX1;
    
    				// This appears to depend on an implicit conversion from
    				// unsigned opcode down to BYTE, to deliberately lose data and have
    				// opcode >= 0x100 wrap around to 0.
    				m_pOutputBuffer[offset++] = (opcode & 0xFF);
    			}
    
    			assert(pInstr->m_opcode < _countof(s_OpCodeFlags));
    			BYTE flags = s_OpCodeFlags[pInstr->m_opcode];
    			switch (flags)
    			{
    			case 0:
    				break;
    			case 1:
    				*(UNALIGNED INT8 *)&(pIL[offset]) = pInstr->m_Arg8;
    				break;
    			case 2:
    				*(UNALIGNED INT16 *)&(pIL[offset]) = pInstr->m_Arg16;
    				break;
    			case 4:
    				*(UNALIGNED INT32 *)&(pIL[offset]) = pInstr->m_Arg32;
    				break;
    			case 8:
    				*(UNALIGNED INT64 *)&(pIL[offset]) = pInstr->m_Arg64;
    				break;
    			case 1 | OPCODEFLAGS_BranchTarget:
    				fBranch = true;
    				break;
    			case 4 | OPCODEFLAGS_BranchTarget:
    				fBranch = true;
    				break;
    			case 0 | OPCODEFLAGS_Switch:
    				*(UNALIGNED INT32 *)&(pIL[offset]) = pInstr->m_Arg32;
    				offset += sizeof(INT32);
    				break;
    			default:
    					assert(false);
    				break;
    			}
    			offset += (flags & OPCODEFLAGS_SizeMask);
    		}
    		m_IL.m_offset = offset;
    
    		if (fBranch)
    		{
    			bool fTryAgain = false;
    			unsigned switchBase = 0;
    
    			// Go over all control flow instructions and resolve the targets
    			for (ILInstr * pInstr = m_IL.m_pNext; pInstr != &m_IL; pInstr = pInstr->m_pNext)
    			{
    				unsigned opcode = pInstr->m_opcode;
    
    				if (pInstr->m_opcode == CEE_SWITCH)
    				{
    					switchBase = pInstr->m_offset + 1 + sizeof(INT32) * (pInstr->m_Arg32 + 1);
    					continue;
    				}
    				if (opcode == CEE_SWITCH_ARG)
    				{
    					// Switch args are special
    					*(UNALIGNED INT32 *)&(pIL[pInstr->m_offset]) = pInstr->m_pTarget->m_offset - switchBase;
    					continue;
    				}
    
    				BYTE flags = s_OpCodeFlags[pInstr->m_opcode];
    
    				if (flags & OPCODEFLAGS_BranchTarget)
    				{
    					int delta = pInstr->m_pTarget->m_offset - pInstr->m_pNext->m_offset;
    
    					switch (flags)
    					{
    					case 1 | OPCODEFLAGS_BranchTarget:
    						// Check if delta is too big to fit into an INT8.
    						// 
    						// (see #pragma at top of file)
    						if ((INT8)delta != delta)
    						{
    							if (opcode == CEE_LEAVE_S)
    							{
    								pInstr->m_opcode = CEE_LEAVE;
    							}
    							else
    							{
    								assert(opcode >= CEE_BR_S && opcode <= CEE_BLT_UN_S);
    								pInstr->m_opcode = opcode - CEE_BR_S + CEE_BR;
    								assert(pInstr->m_opcode >= CEE_BR && pInstr->m_opcode <= CEE_BLT_UN);
    							}
    							fTryAgain = true;
    							continue;
    						}
    						*(UNALIGNED INT8 *)&(pIL[pInstr->m_pNext->m_offset - sizeof(INT8)]) = delta;
    						break;
    					case 4 | OPCODEFLAGS_BranchTarget:
    						*(UNALIGNED INT32 *)&(pIL[pInstr->m_pNext->m_offset - sizeof(INT32)]) = delta;
    						break;
    					default:
    					assert(false);
    
    						break;
    					}
    				}
    			}
    
    			// Do the whole thing again if we changed the size of some branch targets
    			if (fTryAgain)
    				goto again;

    And the part that i inject is 

    	pNewInstr = pilr->NewILInstr();
    	#ifdef _WIN64
    		pNewInstr->m_opcode = CEE_LDC_I8;
    		pNewInstr->m_Arg64 = functionID;
    	#else
    		pNewInstr->m_opcode = CEE_LDC_I4;
    		pNewInstr->m_Arg32 = functionID;
    	#endif
    		pilr->InsertBefore(pInsertProbeBeforeThisInstr, pNewInstr);
    		
    		pNewInstr = pilr->NewILInstr();
    		pNewInstr->m_opcode = CEE_LDC_I4;
    		pNewInstr->m_Arg32 =  (funcType == SERV_NAME_GET)?NORMAL_CALLS:funcType;													//Type OF Function
    		pilr->InsertBefore(pInsertProbeBeforeThisInstr, pNewInstr);
    
    		pNewInstr = pilr->NewILInstr();
    		pNewInstr->m_opcode = CEE_CALL;
    		pNewInstr->m_Arg32 = mdProbeRef;
    		pilr->InsertBefore(pInsertProbeBeforeThisInstr, pNewInstr);

    If i remove the function Type Il instruction (one of the arguments) to mdProbeRef(Entry/Exit helper function) . Then it works. 

    Those values(functionID and function Type) i pass from C++ code. 

    Tuesday, June 7, 2016 4:51 AM
  • I'm not familiar with the library you are using, but I'll make a guess anyway :)

    Based on how you are using it, I assume the library treats switch jump targets as separate instructions, rather than having one variable length instruction. If this is true, then you might want to reconsider emitting the opcode for such pseudo instructions. If not then you need to reconsider how you handle switch instructions just about everywhere else.

    // One instruction produces 6 bytes in the worst case

    6 bytes for an instruction is by no means the worst case, ldc.i8 and ldc.r8 are both 9 bytes long.

    	case 0 | OPCODEFLAGS_Switch:
    		*(UNALIGNED INT32 *)&(pIL[offset]) = pInstr->m_Arg32;
    		offset += sizeof(INT32);
    		break;

    You didn't set fBranch like you did for '1 | OPCODEFLAGS_BranchTarget' and '4 | OPCODEFLAGS_BranchTarget', does this mean that a method containing a switch but no other branches will not have the switch targets updated?

    When targeting x86, you emit FunctionID using ldc.i4 but then pass it as an unsigned int64 argument to your function, peverify complains about this sort of thing so its probably worth fixing (should emit a conv.u8 just after the ldc.i4 instruction).

    Where do you update the exception handler table?

        If i remove the function Type Il instruction (one of the arguments) to mdProbeRef(Entry/Exit helper function) . Then it works.

    It's not clear what you mean. If you mean that commenting out exactly the following four lines makes it work, then you might want to verify the signature of the method referenced by mdProbeRef (the signature you passed into IMetaDataEmit::DefineMemberRef).

    	pNewInstr = pilr->NewILInstr();
    	pNewInstr->m_opcode = CEE_LDC_I4;
    	pNewInstr->m_Arg32 =  (funcType == SERV_NAME_GET)?NORMAL_CALLS:funcType;													//Type OF Function
    	pilr->InsertBefore(pInsertProbeBeforeThisInstr, pNewInstr);



    Tuesday, June 7, 2016 2:52 PM
  • Hi Brian ,

    Thanks for ur reply with patience. It helps a lot.!

    1.There are no issues in the signature that i pass , i have double verified it. 

    2. I changed the 6 bytes to 9 bytes and still it dint work out. 

    I had followed the il injecting (Export and Import codes in ilrewrite.cpp ) part blindly from ilRewriteProfiler from the link - ILRewrite10Source

    http://clrprofiler.codeplex.com/SourceControl/list/changesets?branch=master

    By taking the Ilrewrite.cpp and i have added up few more helper functions to get my needs done and appropriate opcodes for that in AddProbe(..) function.

    From the beginning of my development till now i have'nt faced any invalid code exception as i got in Windows 2016. 

     for ur question -  "Where do you update the exception handler table?"

    I did not update any separate exception handler table - which i should do for sure - Can i get some sample codes and links to learn about that in detail?

    But for now , To capture the intermediate functions when exception is thrown I call the Exit call logging function from "ExceptionSearchFunctionEnter" call back(except the function that thrown the exception). 

    Another thing is , for injecting helper function probe at the method exit I just inject only before all the "return" opcodes(considering it to be the end of the method) - Kindly check the ilrewrite.cpp from that project i linked above . Is that correct ? or should i consider any other opcodes additionally as the method exit ?

    Thanks

    Thursday, June 9, 2016 5:52 AM
  • If it were me debugging this, my top priority would be to identify which function is triggering the exception (the function with invalid code, I'm fairly sure that the exception is thrown by the jit or pre-jit verification. Either way the method will not be on the stack so you will probably need to check which was the last method jitted before the exception). My second step would then be to get the raw bytes passed to SetILFunctionBody for that method and decompile them, to see if it looks sane.

    2. I changed the 6 bytes to 9 bytes and still it dint work out. 


    To be honest, I wasn't expecting that to be the cause, these instructions are relatively uncommon and the average size is probably less than 6 anyway (unless switches get involved, but that doesn't matter if you are treating each jump target as its own pseudo-instruction).

    I did not update any separate exception handler table - which i should do for sure - Can i get some sample codes and links to learn about that in detail?

    I don't have any examples for you on this, I can only direct you to ECMA-335 Partition II Section 25.4 (and 25.4.6 in particular). Basically the method body consists of a method header, followed by IL and then the data sections (I'm sure you are already familiar with the first two by now), the exception handler table will be in one of the data sections.

    But for now , To capture the intermediate functions when exception is thrown I call the Exit call logging function from "ExceptionSearchFunctionEnter" call back

    I'm not entirely sure what you mean, if you mean that you are using ExceptionSearchFunctionEnter to detect when a method exits via an exception, then you should use ExceptionUnwindFinallyEnter instead as ExceptionSearchFunctionEnter means something else and will give misleading information, particularly when you encounter exception filters that call other methods (which will become more common now that C#6 has introduced support for them.)

    Kindly check the ilrewrite.cpp from that project i linked above . Is that correct ? or should i consider any other opcodes additionally as the method exit ?

    It sounds like you already have a plan for leaving a function due to exceptions. ret is probably the only instruction you need ... except for one complication - the tail call. The 'tailcall.' prefix opcode can appear before a 'call' or 'callvirt' instruction as a hint to use the tail call optimization (remove the current frame on the call stack just before calling the target method), such calls must be immediately followed by a ret instruction and so inserting your logic between the call and the ret can cause problems.

    Note: If you are instrumenting 'only' to call a helper method with the FunctionID (and stuff that can be statically determined from it's metadata) then you might want to look into using the ELT hooks instead of instrumenting. They are easier to use, but won't work if you need to call back into managed code (eg. accessing a property on an argument).


    • Edited by Brian Reichle Thursday, June 9, 2016 11:14 AM
    • Marked as answer by Selva VS Thursday, June 9, 2016 12:02 PM
    Thursday, June 9, 2016 11:10 AM
  • Thanks Brian, Will get back..! 
    • Edited by Selva VS Thursday, June 9, 2016 12:03 PM
    Thursday, June 9, 2016 12:02 PM
  • Just another small question ..

    I am using gacutil.exe to add helper assembly(that contains the function call definitions that are injected) into GAC. If i am not wrong, can i follow this in production environments ?


    • Edited by Selva VS Friday, June 17, 2016 12:25 PM
    Friday, June 17, 2016 12:23 PM
  • gacutil.exe comes as part of visual studio, so you probably won't be able to rely on your production environment having it. Instead, you will need to create an installer.
    Friday, June 17, 2016 11:51 PM