5

Consider the following code:

if (IsDebuggingEnabled) { 
   instance.Log(GetDetailedDebugInfo()); 
}

GetDetailedDebugInfo() may be an expensive method, so we only want to call it if we're running in debug mode.

Now, the cleaner alternative is to code something like this:

instance.Log(() => GetDetailedDebugInfo());

Where .Log() is defined such as:

public void Log(Func<string> getMessage)
{
    if (IsDebuggingEnabled) 
    {
        LogInternal(getMessage.Invoke());
    }
}

My concern is with performance, preliminary testing doesn't show the second case to be particularly more expensive, but I don't want to run into any surprises if load increases.

Oh, and please don't suggest conditional compilation because it doesn't apply to this case.

(P.S.: I wrote the code directly in the StackOverflow Ask a Question textarea so don't blame me if there are subtle bugs and it doesn't compile, you get the point :)

andreialecu
  • 3,639
  • 3
  • 28
  • 36
  • Easy enough to simulate increased load; you can set up a test case to run both options inside tight loops for a few tens of thousands of iterations and compare. – Amber Aug 13 '09 at 00:39

7 Answers7

5

No, it shouldn't have a bad performance. After all, you'll be calling it only in debug mode where performance is not at the forefront. Actually, you could remove the lambda and just pass the method name to remove the overhead of an unnecessary intermediate anonymous method.

Note that if you want to do this in Debug builds, you can add a [Conditional("DEBUG")] attribute to the log method.

Mehrdad Afshari
  • 414,610
  • 91
  • 852
  • 789
  • Er, what about the fact that lambda, whether called or not, captures variables, and therefore forces them to be hoisted from the stack onto heap? This can actually affect perf quite a bit, as JIT is much more vary of caching field values in registers, so it's likely to do extra memory loads & stores when variable is captured - and you will really notice the difference in a tight loop. – Pavel Minaev Aug 13 '09 at 08:22
  • 1
    @Pavel: In general, this is true. But for OP's purpose, there's no captured variable. – Mehrdad Afshari Aug 13 '09 at 08:27
  • I mentioned that conditional compilation does NOT apply to this case. The code I wrote as a sample is just a simple test case, my production code is entirely unrelated to logging and debug mode - but should work in a similar way. – andreialecu Aug 13 '09 at 10:36
  • @legenden: I mentioned that for the sake of completeness. The first paragraph of the answer applies anyway. – Mehrdad Afshari Aug 13 '09 at 10:39
  • @Mehrad: It doesn't really apply, because I won't necessarily be calling it JUST in debug mode. Please make abstraction of what my little sample implies. In a real application the condition may not be "IsInDebugMode" but something entirely different which can depend on a multitude of factors - and can be True now, and False on the next call. – andreialecu Aug 13 '09 at 15:38
  • OK. Ignore the second paragraph for this case. The first paragraph still applies. The only cost you are paying if you use `Log(GetDetailedDebugInfo);` (note that there are no parens here.) will be the cost of delegate instantiation (which is very small), the method call and the `if` statement. – Mehrdad Afshari Aug 13 '09 at 15:46
  • +1 for mentioning the often underestimated [Conditional("DEBUG")] – Vlad May 16 '12 at 11:39
3

There is a difference in performance. How significant it is will depend on the rest of your code so I would recommend profiling before embarking on optimisations.

Having said that for your first example:

if (IsDebuggingEnabled) 
{ 
    instance.Log(GetDetailedDebugInfo()); 
}

If IsDebuggingEnabled is static readonly then the check will be jitted away as it knows it can never change. This means that the above sample will have zero performance impact if IsDebuggingEnabled is false, because after the JIT is done the code will be gone.

instance.Log(() => GetDetailedDebugInfo());

public void Log(Func<string> getMessage)
{
    if (IsDebuggingEnabled) 
    {
        LogInternal(getMessage.Invoke());
    }
}

The method will be called every time instance.Log is called. Which will be slower.

But before expending time with this micro optimization you should profile your application or run some performance tests to make sure this is actually a bottle neck in your application.

trampster
  • 8,598
  • 4
  • 37
  • 52
3

I was hoping for some documentation regarding performance in such cases, but it seems that all I got were suggestions on how to improve my code... No one seems to have read my P.S. - no points for you.

So I wrote a simple test case:

    public static bool IsDebuggingEnabled { get; set; }


    static void Main(string[] args)
    {
        for (int j = 0; j <= 10; j++)
        {
            Stopwatch sw = Stopwatch.StartNew();
            for (int i = 0; i <= 15000; i++)
            {
                Log(GetDebugMessage);
                if (i % 1000 == 0) IsDebuggingEnabled = !IsDebuggingEnabled;
            }
            sw.Stop();
            Console.WriteLine(sw.ElapsedMilliseconds);
        }

        Console.ReadLine();
        for (int j = 0; j <= 10; j++)
        {
            Stopwatch sw = Stopwatch.StartNew();
            for (int i = 0; i <= 15000; i++)
            {
                if (IsDebuggingEnabled) GetDebugMessage();
                if (i % 1000 == 0) IsDebuggingEnabled = !IsDebuggingEnabled;
            }
            sw.Stop();
            Console.WriteLine(sw.ElapsedMilliseconds);
        }
        Console.ReadLine();
    }

    public static string GetDebugMessage()
    {
        StringBuilder sb = new StringBuilder(100);
        Random rnd = new Random();
        for (int i = 0; i < 100; i++)
        {
            sb.Append(rnd.Next(100, 150));
        }
        return sb.ToString();
    }

    public static void Log(Func<string> getMessage)
    {
        if (IsDebuggingEnabled)
        {
            getMessage();
        }
    }

Timings seem to be exactly the same between the two versions. I get 145 ms in the first case, and 145 ms in the second case

Looks like I answered my own question.

andreialecu
  • 3,639
  • 3
  • 28
  • 36
1

You can also do this:

// no need for a lambda
instance.Log(GetDetailedDebugInfo)

// Using these instance methods on the logger
public void Log(Func<string> detailsProvider)
{
    if (!DebuggingEnabled)
        return;

    this.LogImpl(detailsProvider());
}

public void Log(string message)
{
    if (!DebuggingEnabled)
        return;

    this.LogImpl(message);
}

protected virtual void LogImpl(string message)
{
    ....
}
Sam Harwell
  • 97,721
  • 20
  • 209
  • 280
0

Call getMessage delegate directly instead of calling Invoke on it.

if(IsDebuggingEnabled)
{
  LogInternal(getMessage());
}

You should also add null check on getMessage.

Mehmet Aras
  • 5,284
  • 1
  • 25
  • 32
  • My initial comment included an incorrect statement saying that calling the delegate directly instead of calling Invoke on it would be faster. However, I was wrong and I removed that comment. I wrote a small console application where I invoked a delegate of type Func both by directly and also by calling Invoke on it. I then looked at the generated IL with ildasm tool and the IL was the same for both calls: callvirt instance !0 class[System.Core]System.Func'1::Invoke() – Mehmet Aras Aug 13 '09 at 01:35
0

Standard answers:

  • If you gotta do it, you gotta do it.
  • Loop it 10^9 times, look at a stopwatch, & that tells you how many nanoseconds it takes.
  • If your program is big, chances are you have bigger problems elsewhere.
Mike Dunlavey
  • 40,059
  • 14
  • 91
  • 135
-3

I believe delegates create a new thread, so you may be right about it increasing performance. Why not set up a test run like Dav suggested, and keep a close eye on the number of threads spawned by your app, you can use Process Explorer for that.

Hang on! I've been corrected! Delegates only use threads when you use 'BeginInvoke'... so my above comments don't apply to the way you're using them.

Chris
  • 39,719
  • 45
  • 189
  • 235