MethodBase.GetCurrentMethod() Performance?

Question

I have written a log class and a function as in the following code:

Log(System.Reflection.MethodBase methodBase, string message)

Every time I log something I also log the class name from the methodBase.Name and methodBase.DeclaringType.Name.

I read the following post Using Get CurrentMethod and I noticed that this method is slow.

Should I use the this.GetType() instead of System.Reflection.MethodBase or I should manually log the class/method name in my log e.g. Log("ClassName.MethodName", "log message)? What is the best practice?

Sonneteer

@loannis, similar question is asked here. Check out the link #1467240 – Andrews

From daniels answer "this.GetType() required 2.5 ns per call while MethodBase.GetCurrentMethod().DeclaringType required 2490 ns per call - so you have a speed up of about factor 1200." – Andrews

@Ramesh: Did you notice that was exactly the same question (s)he already linked to in the question? – Heraclitean

Answer 1

It really depends.

If you use the this.GetType() approach you will lose the method information, but you will have a big performance gain (apparently a factor of 1200, according to your link).

If you offer an interface that lets the caller supply strings (e.g. Log("ClassName.MethodName", "log message"), you will probably gain even better performance, but this makes your API less friendly (the calling developer has to supply the class name and method name).

Marysa

Answer 2

I know this is an old question, but I figured I'd throw out a simple solution that seems to perform well and maintains symbols

static void Main(string[] args)
    {
        int loopCount = 1000000; // 1,000,000 (one million) iterations
        var timer = new Timer();

        timer.Restart();
        for (int i = 0; i < loopCount; i++)
            Log(MethodBase.GetCurrentMethod(), "whee");
        TimeSpan reflectionRunTime = timer.CalculateTime();

        timer.Restart();
        for (int i = 0; i < loopCount; i++)
            Log((Action<string[]>)Main, "whee");
        TimeSpan lookupRunTime = timer.CalculateTime();

        Console.WriteLine("Reflection Time: {0}ms", reflectionRunTime.TotalMilliseconds);
        Console.WriteLine("    Lookup Time: {0}ms", lookupRunTime.TotalMilliseconds);
        Console.WriteLine();
        Console.WriteLine("Press Enter to exit");
        Console.ReadLine();

    }

    public static void Log(Delegate info, string message)
    {
        // do stuff
    }

    public static void Log(MethodBase info, string message)
    {
        // do stuff
    }

    public class Timer
    {
        private DateTime _startTime;

        public void Restart()
        {
            _startTime = DateTime.Now;
        }

        public TimeSpan CalculateTime()
        {
            return DateTime.Now.Subtract(_startTime);
        }
    }

Running this code gives me the following results:

Reflection Time: 1692.1692ms
    Lookup Time: 19.0019ms

Press Enter to exit

For one million iterations, that's not bad at all, especially compared to straight up reflection. The method group is being cast to a Delegate type, you maintain a symbolic link all the way into the logging. No goofy magic strings.

Malachite

If you are basing your calculations on the exact code you posted, with nothing actually happening in the Log methods themselves, wouldn't you expect the delegate route to use less time, because it doesn't really do anything? Are you actually able to get the name of the method you are passing to the Log(Delegate info... method? – Subsistent

As @Subsistent expected, accessing the Name property in the Log-methods makes the difference. I modified them to return MethodBase.Name and Delegate.Method.Name, respectively. My results then became Reflection Time: 1178,6813ms Lookup Time: 482,2953ms. Still, the "Lookup"-approach leads to faster execution. – Bewray