Skip to main content
edited tags
Link
Mathieu Guindon
  • 75.1k
  • 18
  • 191
  • 463
Source Link
Alex
  • 137
  • 1
  • 5

Async Log4net logging handler - High CPU usage on async call

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?