Case 17: The "Invisible" Cost of Logging

The Story

Imagine a high-traffic ASP.NET Core API. To make debugging easier, developers have added many detailed log statements throughout the code.

In the production environment, even though all the database queries are fast, the application seems slow and uses more CPU than expected.

The Bottleneck Analysis

Logging is not a "free" operation. There are two main bottlenecks that often occur.

1. The I/O Cost of the "Sink"

A "sink" is the destination for your logs (e.g., the console, a file, or a network service like Seq or Datadog).

• The Problem: If the logging framework is configured to write to a file synchronously, every time you call _logger.LogInformation(...), the request-handling thread is blocked while it waits for the data to be written to the disk. This is blocking I/O and a performance killer.
• The Solution: Use asynchronous sinks. Modern logging frameworks like Serilog and NLog all support this. They will put the log message into a queue in memory, and a separate background thread will handle writing it to the disk, freeing up the request thread immediately.

2. The Cost of Creating the Log Message

Writing the log is only part of the story. Preparing the data to be logged can also be expensive, especially if that log level is not even enabled.

• Problematic Code (Using String Interpolation):

  // Assume 'user' is a complex object
  _logger.LogDebug($"Processing request for user: {JsonSerializer.Serialize(user)}");

  • The Problem: The JsonSerializer.Serialize(user) and the string concatenation will be executed BEFORE the LogDebug method checks if the "Debug" log level is actually enabled.
  • The Result: In a production environment (which usually only enables "Information" level and above), your application is constantly serializing large objects and creating complex strings just to... throw them away immediately. This is a huge waste of CPU.

• The Solution: Use Structured Logging

  // Just pass the object, don't serialize it yourself
  _logger.LogDebug("Processing request for user: {@User}", user);

  • How it works: The logging framework checks the log level first. Only if the "Debug" level is enabled will it perform the serialization of the user object. The expensive operation doesn't happen unnecessarily.

---

Rules for Optimizing Logging

1. Use Asynchronous Sinks: Always configure your logging to write asynchronously in a production environment.
2. Always Use Structured Logging: Use message templates ("Processing {UserId}") instead of string interpolation ($"Processing {userId}").
3. Set Appropriate Log Levels: Run production at the Information or Warning level. Only enable Debug or Trace when you need to diagnose a problem.
4. Avoid Logging Large Objects on the "Hot Path": Be careful about logging large objects or logging inside high-frequency loops.

Conclusion

Logging is an essential tool, but it comes with a performance cost. By using modern logging frameworks correctly (using async sinks, message templates, and appropriate log levels), you can get the detailed diagnostic information you need without sacrificing your application's performance.