Async Log4net logging handler - High CPU usage on async call

Question

I've got a LoggingMessageHandler that incoming requests on my WebApi application filter through.

public class LoggingMessageHandler : DelegatingHandler
{
    public ILogManager LogManager { get; set; } //injected

    protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, System.Threading.CancellationToken cancellationToken)
    {
        var logger = SetupLogger(request);

        var correlationId = request.GetCorrelationId().ToString();

        var requestInfo = await LogRequest(request, logger, correlationId);

        var response = await base.SendAsync(request, cancellationToken);

        await LogResponse(response, logger, correlationId, requestInfo);

        response.Headers.Add("X-Correlation-Id", correlationId);

        return response;
    }

    private ILogger SetupLogger(HttpRequestMessage request)
    {
        var loggerName = request.RequestUri.AbsolutePath.Replace("/", "-");
        var logger = LogManager.GetLogger(loggerName);
        return logger;
    }

    private async Task<string> LogRequest(HttpRequestMessage request, ILogger logger, string correlationId)
    {
        var requestInfo = string.Format("{0} {1}", request.Method, request.RequestUri);

        var requestMessage = "";

        if (request.Content != null)
            requestMessage = await request.Content.ReadAsStringAsync();

        await LogMessageAsync(logger, "Request", correlationId, requestInfo, requestMessage);
        return requestInfo;
    }

    private async Task LogResponse(HttpResponseMessage response, ILogger logger, string correlationId, string requestInfo)
    {
        var responseMessage = string.Empty;

        if (response.IsSuccessStatusCode)
        {
            if (response.Content != null)
                responseMessage = await response.Content.ReadAsStringAsync();
        }
        else
            responseMessage = response.ReasonPhrase;

        await LogMessageAsync(logger, "Response", correlationId, requestInfo, responseMessage);
    }

    private async Task LogMessageAsync(ILogger logger, string type, string correlationId, string requestInfo, string body)
    {
        await Task.Run(() => logger.Info("{0} - {1} - API - {2}: \r\n{3}", correlationId, requestInfo, type, body));
    }
}

When I run ANTS profiler, and test my application, > 70% of the CPU time is spent on this one line:

await Task.Run(() => logger.Info("{0} - {1} - API - {2}: \r\n{3}", correlationId, requestInfo, type, body));

Is that expected?

Am I doing something wrong?

Answer 1

I haven't used Autofac, but with Ninject you can use the logging extensions to automagically inject an ILogger into any class' constructor, so you can stick to constructor injection (which is always preferable over all other kinds of dependency injection techniques), with the only drawback that you have a using Ninject.Extensions.Logging; dependency on your module (given that your current code already has dependencies on Log4Net, I don't see it being an issue though).

I haven't used Log4Net either, but you might be reinventing the wheel.

With NLog it looks like you simply put an async attribute in your targets configuration and you're set:

<targets async="true">

And with the IoC container auto-resolving ILogger for you, all you really need is to constructor-inject an ILogger into whatever class requires logging functionality.

---

I would look into implementing similar functionality with Autofac/Log4Net, or see what I get with Ninject/Log4Net or Ninject/NLog logging extensions, both available through NuGet.

Answer 2

Are you using a BufferingForwardingAppender? By default, it makes some very CPU intense calls for every logging statement. This pitfall is not documented.

The short answer is that, when you configure your BufferingForwardingAppender, you need to configure it so it doesn't do expensive things like get a stack trace. (You probably aren't logging the things it's collecting, anyway!)

There's a very good explanation of how to fix this at https://stackoverflow.com/a/11351400

Reconfiguring my BufferingForwardingAppender made a major CPU improvement!