0
\$\begingroup\$

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?

\$\endgroup\$
  • \$\begingroup\$ //injected - are you using an IoC container? \$\endgroup\$ – Mathieu Guindon May 2 '14 at 15:09
  • 1
    \$\begingroup\$ Yes... omitted for brevity (it's Autofac - via property injection) \$\endgroup\$ – Alex May 2 '14 at 15:12
  • \$\begingroup\$ This might be of interest. Log4Net has an async appender that looks readily available (not familiar with Log4Net). \$\endgroup\$ – Mathieu Guindon May 2 '14 at 15:15
3
\$\begingroup\$

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.

\$\endgroup\$
  • \$\begingroup\$ This isn't really relevant to the problem. Matt's Mug is asking why log4net is consuming so much CPU. \$\endgroup\$ – Andrew Rondeau May 28 '15 at 19:29
  • \$\begingroup\$ @AndrewRondeau swapping for a less bugged-up log provider sounds relevant to me. \$\endgroup\$ – Mathieu Guindon May 28 '15 at 19:46
  • \$\begingroup\$ @AndrewRondeau problems to be solved should be solved on Stack Overflow. Here, any and all facets of the code are up for review. \$\endgroup\$ – RubberDuck May 28 '15 at 20:01
  • 1
    \$\begingroup\$ @RubberDuck not my best answer though. looking at it again, I'm tempted to flag myself. \$\endgroup\$ – Mathieu Guindon May 28 '15 at 20:06
2
\$\begingroup\$

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!

\$\endgroup\$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.