Logging is obviously super critical. But, poor logging can result in performance bottlenecks, wasted resources and of course difficulties in log analysis. For example, string interpolation should be avoided in logging.
Why?
We'll find out in this article!
Why is string interpolation problematic
First of all, just to make sure we're on the same page, string interpolation is basically the following:
$"User {user.Name} logged in"
which is super convenient way to construct strings, but it's not suitable for logging. Why?
Performance overhead and wasted resources
When you use string interpolation, the interpolated string is evaluated immediately, EVEN if the log level is disabled.
Insane right?
For Example:
logger.LogDebug($"User {user.Name} logged in at {DateTime.Now}");
In this case, user.Name and DateTime.Now are evaluated, and the interpolated string is ACTUALLY created in memory, regardless of whether the LogDebug level is enabled or not, which means unnecessary CPU and memory usage, especially in production envs where debug logs are typically disabled.
Imagine you had 1000 LogDebug's using interpolated strings in production. You just wasted CPU cycles and memory for literally nothing!
Another downside, is that when you use string interpolation for logging exceptions, you might lose valuable stack trace details.
_logger.LogError($"An error occurred: {ex.Message}");
This only logs the messsage, not the full exception details. Instead, you should pass exception separately, to ensure the full stack trace is logged properly:
_logger.LogError(ex, "An error occurred while processing the request");
A better approach - structured logging
Thankfully, modern logging frameworks such as Serilog and Microsoft.Extensions.Logging support structured logging.
What is structured logging?
logger.LogDebug("User {UserName} logged in at {LoginTime}", user.Name, DateTime.Now);
What did we actually just achieve with this simple change?
Well, first of all, the string WON'T get evaluated unless the log level is enabled, meaning we completely avoid unnecessary computation and memory allocation when log level is disabled. Another pro, is that the log message template and the parameters are passed separately and I'll explain now why this is very important too.
Easier log analysis with tools like Graylog
When logs are written using structured logging, they are stored as structured data (e.g., JSON) rather than plain text. This makes it wayyy easier to use tools like Graylog or whatever you're using, to analyze and visualize logs
Let's do an example
Suppose you log the following message:
logger.LogInformation("Order {OrderId} created by {UserId} with amount {Amount}", orderId, userId, amount);
Structured logging makes sure that logs are stored in JSON format, so the above will be stored as something like that:
{
"Message": "Order 123 created by 456 with amount 100.50",
"OrderId": 123,
"UserId": 456,
"Amount": 100.50
}
- Since OrderId, UserId, and Amount are separate fields in JSON, we can filter logs directly!
- Create dashboards in Grafana to monitor specific metrics (e.g. total orders by user)
- Perform more advanced queries (e.g. find all orders with Amount > 100).
To filter logs where Amount > 100, you can use:
Amount:>100
This will filter the logs from your application, parse the json structure of logs and finally return ONLY the logs where the Amount field is greater than 100
Conclusion
That's all, and remember: logging is an essential part of any application, but how you log matters just as much as what you log