Deep Diving Into “CA2254: Template Should Be a Static Expression” and How to Fix It

You can also read about this in my example repo: CA2254-Logging-Experiments.

Short version

Use string templates instead of string interpolation (or string concat) because bringing structure to our logs helps us more easily read, parse, and query them.

var time = "3:00 PM";

// Don't do this (string interpolation)
_logger.LogInformation($"The time is currently: {time}");

// Do this (message templates)
_logger.LogInformation("The time is currently: {currentTime}", time);

Because that string interpolation in evaluated every time, regardless of log level meaning the code is incurring the memory usage of the interpolation even if it's not logged. This increases garbage collector pressure, and reduces performance.

If you want to know more about CA2254, why structured/semantic logging is useful, and performance metrics behind templating, read on.

What is CA2254?

CA2254: Template should be a static expression is a warning that the log message doesn't have a consistent structure due to being interpolated or concatenated.

The solution is to use a message template, which provides us structured logging and improved performance.

Structured logging

In short, giving structure to our logs helps us more easily read, parse, and query our logs.

The NLog wiki:

Structured logging makes it easier to store and query log-events, as the logevent message-template and message-parameters are preserved, instead of just transforming them into a formatted message.

To take an example from the .NET logging documentation, consider the following logger method:

_logger.LogInformation("Getting item {Id} at {RunTime}", id, DateTime.Now);

For example, when logging to Azure Table Storage:

• Each Azure Table entity can have ID and RunTime properties.
• Tables with properties simplify queries on logged data. For example, a query can find all logs within a particular RunTime range without having to parse the time out of the text message.

Though, it may be the case that you're doing a small hobby project, or throwaway code, or anything that isn't going to have a massive amount of logs to trawl through when a production issue occurs, then you can probably ignore the warning and #pragma it away. However, there are also performance implications of using string interpolation regardless of intent of using full blown structured logging.

Performance

The heading Avoid string interpolation in logging explains:

String interpolation in logging is problematic for performance, as the string is evaluated even if the corresponding LogLevel isn't enabled.

This is because the string interpolated value is evaluated at the time of passing the string into the ILogger call, not after the log message is ready to be sent to a provider. For example if we look at interpolation:

var time = "3:00 PM";

// This interpolated string
_logger.LogInformation($"The time is currently: {time}");

// has the interpolation cost done to it before entering the LogInformation() method, meaning the call ends up being:
_logger.LogInformation($"The time is currently: 3:00 PM");

Contrast this with using a log message template:

var time = "3:00 PM";

// This log template is passed as is to the underlying call without upfront interpolation cost
_logger.LogInformation("The time is currently: {currentTime}", time);

You can see for yourself in the Logger class in Logger.cs where we can pick up a couple of key checks before a log message is written:

1. If there are any providers to log to. E.g. Console, EventSource, EventLog, etc
2. If the right level is enabled for this message for this provider

Only then is work put in to interpolate our string.

Metrics

Let's look at performance metrics. The benchmarks are off the back of the default weather example when creating a new minimal API with some of the randomness and allocations removed. Work is still left in to ensure our benchmarks aren't jitted away. There will be two benchmarks: Interpolation, and Template. They both use LogInformation() for information level logging.

// Interpolation
_logger.LogInformation($"Returning weather forecast. Day 1 summary: {forecast[0].Summary}");

// Template
_logger.LogInformation("Returning weather forecast. Day 1 summary: {summary}", forecast[0].Summary);

Both will log the same string:

"Returning weather forecast. Day 1 summary: Sweltering"

No provider

No log message is written regardless of level.

With no providers to log to, the interpolation occuring creates more allocations than the template - increasing garbage collection pressure. The template allocations are due to calling into a function with a params parameter, leading to an array allocation (I believe).

Console provider with warning log level

The Logger object will attempt to log to the console, but due to the warning log level, none of the information logs will be written.

Same outcome as having no provider.

Console provider with information log level

The Logger object will log the weather string to the console.

When writing a log message, slightly more allocation has come from the template version. However this is acceptable as most logging calls in a production environment are skipped over. Unless needed, it's a poor idea to have logs in production to be at a lower, more verbose level. Meaning there is an overall gain in memory savings, and an overall reduction in GC pressure when templating.

Repo

If you want to run and experiment with this yourself, see my example repo: CA2254-Logging-Experiments.

Links

• CA2254: Template should be a static expression
• Logging in C# and .NET
• Logging in .NET Core and ASP.NET Core
• Logging guidance for .NET library authors
• How to use structured logging by NLog
• ZLogger: A zero allocation text/structured logger (for interest)
• CA2254-Logging-Experiments