How to log elapsed time in Log4Net

Question

I want to log the elapsed time of my APIs. I see here two different approaches:

Using a stopwatch. Create a new stopwatch just after entering the API and then calling stop() just before quitting it (print the elapsed time on the log itself).
Make two log printouts, one just after entering the API, the other just before quitting it. The elapsed time would be "stored" as the time difference between the two log timestamps.

Which approach do you think is the best?

First one seems good but I need to create a new stopwatch everywhere. The second is cleaner but then some math has to be done when reading back the log

I would go for the second option. Polluting your code with stopwatch functionality that isn't used in the code itself seems worse than doing some calculations in code dedicated to getting the time difference. — Alexander Derck, Feb 22 '16 at 09:47
@AlexanderDerck thanks. But then I should find a way to relate the two log lines together. My code is actually a WebAPI and the IP address alone is not enough to link the two log lines (imagine a LAN of PCs behind a router). Can log4net log the thread id? (if such thing exists in .NET) — Gianluca Ghettini, Feb 22 '16 at 09:51
Have a look at [this answer](http://stackoverflow.com/a/2096452/3410196), it's possible — Alexander Derck, Feb 22 '16 at 09:58
The correct way to do this is with a DelegatingHandler in the Web API pipeline - see [this answer](http://stackoverflow.com/a/23732865/43846) for an example, and [this page](http://odetocode.com/blogs/scott/archive/2013/04/04/webapi-tip-7-beautiful-message-handlers.aspx) for context. — stuartd, Feb 22 '16 at 10:41

Good Night Nerd Pride · Accepted Answer · 2016-02-22T14:30:03.013

I'd go with the first option. The creation of a Stopwatch is very cheap. And with a good wrapper the required code in each API method can be as simple as:

public int MyApiMethod()
{
    using (new ExecutionTimeLogger())
    {
        // All API functionality goes inside this using block.
        var theResultValue = 23;
        return theResultValue;
    }
}

The class ExecutionTimeLogger would look something like this:

using System;
using System.Diagnostics;
using System.Runtime.CompilerServices;
using log4net;

public class ExecutionTimeLogger : IDisposable
{
    private readonly ILog log = LogManager.GetLogger("ExecutionTimes");
    private readonly string methodName;
    private readonly Stopwatch stopwatch;

    public ExecutionTimeLogger([CallerMemberName] string methodName = "")
    {
        this.methodName = methodName;
        stopwatch = Stopwatch.StartNew();
    }

    public void Dispose()
    {
        log.Debug(methodName + "() took " + stopwatch.ElapsedMilliseconds + " ms.");
        GC.SuppressFinalize(this);
    }
}

Depending on your logger implementation the output could look something like this:

15:04:23.4477 | DEBUG | ExecutionTimes | MyApiMethod() took 42 ms.

Note that the log output will also be generated when the API method threw an exception inside the using, because the ExecutionTimeLogger instance will be disposed nethertheless.

The methodName parameter will be automatically filled by the compiler because it has the [CallerMemberName] attribute. You don't need to pass it every time you create an ExecutionTimeLogger.

The line GC.SuppressFinalize(this) tells the garbage collector that a call to the finalizer of the ExecutionTimeLogger instance doesn't have to be scheduled, because we know it never created unmanaged resources.

If you are using Unity as the DI framework you could also write a UnityContainerExtension that wraps every method having a certain custom attribute (say LogExecutionTimeAttribute for example) with the required measurement and logging code. That's much more complicated though.

Thanks, could you please elaborate more your answer? What is actually an ExecutionTimeLogger? — Gianluca Ghettini, Feb 22 '16 at 09:54
Upvoted because I didn't know you can pass attributes before a parameter :p — Alexander Derck, Feb 22 '16 at 10:10
@Abbondanza brilliant! only concern is how to pass a log string to the ExecutionTimeLogger() — Gianluca Ghettini, Feb 22 '16 at 13:36
@GianlucaGhettini, well you could pass anything to the constructor, save it in a private field and then re-use it inside `Dispose()`. You could even use lambdas to make it more generic. What is it specifically that you want to do? — Good Night Nerd Pride, Feb 22 '16 at 13:56
@Abbondanza inside the API I could need to log some other stuff, that's it — Gianluca Ghettini, Feb 22 '16 at 15:26
@GianlucaGhettini, that sounds like a totally different concern that happens to also write something to a log file. I would not mix execution time tracing with other logging concerns and just get a separate logger instance inside the API class for that. — Good Night Nerd Pride, Feb 22 '16 at 15:41
I don't think you need to call GC.SuppressFinalize(this) if there is no Finalizer in the class. — Co-der, Feb 07 '20 at 12:24

score 1 · Answer 2 · answered Feb 22 '16 at 09:56

1

I prefer the first approach (using stopwatch).
if your methods are called synchronize you don't have to create a new Stopwatch object for each API call. you can define a global instance of Stopwatch and after calling Stop(),call Reset() , or Restart() to start counting from the beginning.

answered Feb 22 '16 at 09:56

Mohy66

390
2
12

1

The APIs can run concurrently. Is your approach still valid? – Gianluca Ghettini Feb 22 '16 at 09:57
just you cant use single instance of Stopwatch. but be sure , i have used stopwatch a lot and creating lots of instances it isn't time consumable and it doesn't have any memory leaks or other annoying things... – Mohy66 Feb 22 '16 at 10:04

How to log elapsed time in Log4Net

2 Answers2