Outsmarting Yourself with Reflection, Release Mode, and Inlining

The Problem

I have a WPF app that's in testing that came back with some weird issues this week. The app uses Client Object model to consume SP2010 lists, and UX is a factor in the design, so we have decided to do some Metrics recording to see how people interact with the app. We want to know what features people use, and which efforts were wasted.

Strangely, we started noticing that the names of the Metrics, which were also being written to a SP list, were displaying some incorrect results. Names like "ShowAllItemsOpened" were instead "showAllMenuItem_Click". What's that you say? Clearly that's the name of an event handler! Well you'd be right! But it worked before! What changed in testing? First, some background information ...

Reflecting on Reflection

Sometimes I try way too hard to be brilliant when I code. When I created these metrics, I decided to be lazy efficient, and save myself some effort. I do this trick when I write logging code where — if I’m in method B, which was called by method A — I find the name of method A. It’s great for riddling code with debug statements and not having to type the name of the method when I do it. For example, if method A calls method B, and I have the following line of code in method B…

string methodName = new StackFrame(1,true).GetMethod().Name

…methodName would have the value of “A”, which is the method that called it. Clever, right? This sort of thing is called reflection. Of course, reflection has a bit of a performance hit, so you should be careful when you use it.

In any event, this trick allowed me to make a method called:

public void ShowAllMenuItem() { RecordMetric(); } 

I don’t have to define the name of the metric as “ShowAllMenuItem” because the name of the method does that for me. Everything is kept in sync.

The Hidden Dangers of Optimization

In C#, you can choose to build your code in debug mode or release mode (there are actually more options, but let’s keep it simple). In debug mode, the code is compiled and acts almost like a scripting language. This allows you to attach to a process and debug it line-by-line. But when you release code to production, you use release mode and C# optimizes your code. For a good explanation of how, read Hello, I am a Compiler.

Ok, so why would an optimally compiled program be a problem? The kiss of death here is inlining.

Inlining is an optimization technique that the compiler uses, which is explained in the link above. To summarize, inlining is like the transitive property in math. If A=B, and B=C, then A=C. So if method A (showAllMenuItem_Click) calls method B (ShowAllMenuItem) and method B just calls method C (RecordMetric), inlining says “hey, let’s cut out the middle man. Let’s just have method A call method C and be done with it.”

So when the application is running, ShowAllMenuItem doesn’t exist. RecordMetric says “Hey, who called me? Oh, showAllMenuItem_Click! Okay!”

So What Do We Do About It?

There are a couple of options.

First, I could be less lazy efficient, and just put a string in each method. RecordMetric() should be called with a string paramater which is used for the metric name. It’s really not that much more work.

But if I insist on sticking with what I’ve done, C# provides a decorator that you can put on a method that tells the compiler not to use inlining.

[MethodImpl(MethodImplOptions.NoInlining)]

In the end, I've decided to do away with the reflection. Recording metrics is something that will happen constantly, and the performance hit of using reflection is not trivial. But I hope that this will give you a little insight into how the compiler works, the differences between release and debug mode, and the woes of using reflection carelessly.