Take the 2-minute tour ×
Code Review Stack Exchange is a question and answer site for peer programmer code reviews. It's 100% free, no registration required.

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?

share|improve this question
    
//injected - are you using an IoC container? –  Mat's Mug May 2 '14 at 15:09
1  
Yes... omitted for brevity (it's Autofac - via property injection) –  Alex May 2 '14 at 15:12
    
This might be of interest. Log4Net has an async appender that looks readily available (not familiar with Log4Net). –  Mat's Mug May 2 '14 at 15:15

2 Answers 2

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.

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

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 http://stackoverflow.com/a/11351400

Reconfiguring my BufferingForwardingAppender made a major CPU improvement!

share|improve this answer

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

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