Search code examples
.netserilog

What is more efficient logging in Serilog in .NET?

I am using Serilog in .NET core application for logging.

I am logging in two ways and I am not sure if one is more efficient than the other.

  1. Using $ Prefix to serialize the properties
 _logger.LogInformation($"consumer:{_consumer.ConsumerName}. clientId:{_consumer.ClientId}." +
                                       $"max_handle_latency:{_maxHandleMessageLatencyInterval}." +
                                       $"total_consume_requests:{_numConsumingOperatonsInInterval}. topics:{topics}");
  1. Without using $ - by passing parameters to template.
 _logger.LogInformation("producer:{name}. total_produce_requests:{total_produce_requests}. max_latency:{max_latency}. intervalInMs:{interval_in_ms}. topics:{topics}",
                                  _kafkaProducer.Name,
                                  _numProduceOperationsInInterval,
                                  _maxLatencyInInterval,
                                  _producerIntervalInMs,
                                  string.Join(",", topics));

This results in these two different log statements. Look at the MessageTemplate and the Properties.

1.

{
    "Timestamp": "2020-09-29T11:58:39.0343478-07:00",
    "Level": "Information",
    "MessageTemplate": "consumer:DotNetCoreReferenceApplication-myhost#consumer-7. clientId:DotNetCoreReferenceApplication-BL-9HQ76S2.max_handle_latency:35.total_consume_requests:1356. topics:bl-perf",
    "Properties": {
        "SourceContext": "MySvc.Messaging.EventsHub.MyConsSvc",
        "ThreadId": 27,
        "ActionId": "c1bbd73f-634b-44dc-aa3e-b2c09a097fd1",
        "ActionName": "MySvc.Messaging.Api.Controllers.ConsumerConfigController.SetConsumerConfig (MySvc.Messaging.Api)",
        "RequestId": "0HM34L5IO01I8:00000001",
        "RequestPath": "/eventhub/consumer/setconfiguration",
        "SpanId": "|6bb4afcf-4eafc985509764f0.",
        "TraceId": "6bb4afcf-4eafc985509764f0",
        "ParentId": "",
        "ConnectionId": "0HM34L5IO01I8"
    }
}

 {
        "Timestamp": "2020-09-29T12:00:39.0139328-07:00",
        "Level": "Information",
        "MessageTemplate": "producer:{name}. total_produce_requests:{total_produce_requests}. max_latency:{max_latency}. intervalInMs:{interval_in_ms}. topics:{topics}",
        "Properties": {
            "name": "DotNetCoreReferenceApplication-mydevbox#producer-6",
            "total_produce_requests": 0,
            "max_latency": 0,
            "interval_in_ms": 60000,
            "topics": "",
            "SourceContext": "MySvc.Messaging.EventsHub.Producer.EventBusProducer",
            "ThreadId": 8,
            "ActionId": "c1bbd73f-634b-44dc-aa3e-b2c09a097fd1",
            "ActionName": "MySvc.Messaging.Api.Controllers.ConsumerConfigController.SetConsumerConfig (MySvc.Messaging.Api)",
            "RequestId": "0HM34L5IO01I8:00000001",
            "RequestPath": "/eventshub/perf/csmr/config",
            "SpanId": "|6bb4afcf-4eafc985509764f0.",
            "TraceId": "6bb4afcf-4eafc985509764f0",
            "ParentId": "",
            "ConnectionId": "0HM34L5IO01I8"
        }
    }

While the latter doesn't look as read-able as the first one, it seems to make more sense since you expect a template to be, well a template! So I suspect the second one is more efficient if Serilog does caching of templates or anything of that sort.

The first one looks more readable though but the template includes the actual log statement.

Solution

  • The second one (using the message template) is much more efficient.

    In the first example, the message is always formatted, even if logging at that level is "off". In the second example, formatting will only occur if actually required.

    Using $ (string interpolation) will also thwart Serilog's internal template caching, reducing performance more.

    https://nblumhardt.com/2016/07/event-types-structured-logging-concepts-in-net-4/ has some further discussion of why the template is useful.