A colleague contacted me the other day with an interesting Production problem. Apparently he was walking a StackTrace to derive a method name for logging and in Production it led to NullReferenceExceptions. After he described what he saw, unfortunately I have seen this risky pattern used before and I knew exactly what was wrong.
I cannot reproduce this anywhere other than Production and when I step through it, it does not reveal anything either. Strangely enough, after I added a bunch of logging & tracing routines to a few of the call paths and redeployed to production it no longer occurred in those paths.
- The Colleague
For some strange reason, people just love doing this without realizing what might happen. Lets look at a small sample I wrote to demonstrate the scenario he employed:
using System;
using System.Diagnostics;
using System.Reflection;
public sealed class Program
{
static void Main()
{
try
{
DoSomething();
}
catch
{
}
}
static void DoSomething()
{
DoSomethingElse();
}
static void DoSomethingElse()
{
string className;
string methodName;
SampleHelper.RetrieveCallersClassAndMethodName(out className, out methodName, 1);
Console.WriteLine(string.Format("I was called by {0}/{1}.",
className, methodName));
}
}
public static class SampleHelper
{
public static void RetrieveCallersClassAndMethodName(out string className, out string methodName, int stackLevelOffset)
{
StackFrame frame = new StackFrame(stackLevelOffset);
MethodBase methodBase = frame.GetMethod();
className = methodBase.DeclaringType.Name;
methodName = methodBase.Name;
}
}
Notice the stack offset is set to 1
SampleHelper.RetrieveCallersClassAndMethodName(out className, out methodName, 1);
If you run this, it will lead to the following result:
I was called by Program/DoSomethingElse.
Similarly, if you set the offset to 2 it will lead to the following result:
I was called by Program/DoSomething.
So far this looks pretty straightforward. If you run this from Visual Studio (VS) you'll never see any issues with this, but once you've compiled and deployed this to Production your results may vary and you'll likely get a NullReferenceException. The reason for this is simple, but if you're not aware of how the JIT Compiler optimizes IL you'll lose your mind trying to figure it out.
The quickest way to reproduce the Null Reference condition is to set the offset to something like 99999. Run it again, and you'll reproduce the error. What this illustrates is a condition where you attempt to read to a Stack offset that doesn't exist. But wait, shouldn't the 1, 2, 3 offsets always exist. In short... No and to make matters worse, even if they do exist they may no longer be the location you expect. This is why this pattern is so troublesome; not to mention prone to exceptions.
The issue lies in JIT Compiler Optimizations. The truth is, we don't always write code in the most performant manner and method calls can be expensive (relatively speaking). Consequently, the JIT Compiler optimizes IL to be more performant for a given processor. These optimizations may lead to methods being combined or broken apart, which is why the above pattern leads to unpredictable results. The good news is, we're not completely powerless. The rules revolving around this process are well documented, so knowing how it works will help you assess and/or mitigate your risks of being a victim of optimizations. Here is a list of conditions under which methods will NOT be inlined, if your code does not meet one of these conditions your code is subject to optimizations:
- Methods that are greater than 32 bytes of IL will not be inlined, this explains why the addition of logging functions in the previous report stopped this from occurring. Essentially, the impacted methods crossed the 32 byte threshold
- Virtual functions are not inlined
- Methods that have complex flow control will not be in-lined. Complex flow control is any flow control other than if/then/else; in this case, switch or while
- Methods that contain exception-handling blocks are not inlined, though methods that throw exceptions are still candidates for inlining
- If any of the method's formal arguments are structs, the method will not be inlined
Although not on the official Microsoft list of conditions, there are three other implicit rules; the first two of which explain why this is not reproducible in VS or outside the Production environment.
- Inlining is disabled when a debugger is attached
- By default, inlining is disabled when compiling in Debug mode
- Inlining will be disabled when any method is decorated with the MethodImplAttribute and the MethodImplOptions.NoInlining is set
[System.Runtime.CompilerServices.MethodImpl(MethodImplOptions.NoInlining)]
If after all this you still want to use this pattern, lets refactor the original code to reduce the risk of optimization issues:
using System;
using System.Diagnostics;
using System.Reflection;
using System.Runtime.CompilerServices;
public sealed class Program
{
[MethodImpl(MethodImplOptions.NoInlining)]
static void Main()
{
try
{
DoSomething();
}
catch
{
}
}
[MethodImpl(MethodImplOptions.NoInlining)]
static void DoSomething()
{
DoSomethingElse();
}
[MethodImpl(MethodImplOptions.NoInlining)]
static void DoSomethingElse()
{
string className;
string methodName;
SampleHelper.RetrieveCallersClassAndMethodName(out className, out methodName, 2);
Console.WriteLine(string.Format("I was called by {0}/{1}.",
className, methodName));
}
}
public static class SampleHelper
{
[MethodImpl(MethodImplOptions.NoInlining)]
public static void RetrieveCallersClassAndMethodName(out string className, out string methodName, int stackLevelOffset)
{
className = string.Empty;
methodName = string.Empty;
StackFrame frame = new StackFrame(stackLevelOffset);
MethodBase methodBase = frame.GetMethod();
if (methodBase == null)
return;
if (methodBase.DeclaringType == null)
return;
className = methodBase.DeclaringType.Name;
methodName = methodBase.Name;
}
}
One final point. Every time I have this discussion someone inevitably asks if they can write code to tell them whether or not their method has been inlined. Practically speaking the answer is No. In fact, you won't even see this in Reflector. Remember, optimizations occur during JIT compilation, not when you're compiling to IL. Additionally, the same code may be inlined differently on two different machines because this process is partially impacted by the type of processor you are running against.
Well that's it... Again, I caution you against using this pattern but if you do need it, pay very close attention, and test this well.
Tags: debugging, design patterns