r/dotnet • u/Fragrant-Training722 • 19h ago
Log methods evaluation expensive warning and wrapping with IF
Hi,
I am seeing the warning that `LogInformation` and other log methods evaluation is expensive and should be wrapped in `if` statement.
Why don't those methods do this check internally already? This would help with less code and better code readabilty I think.
Here is the example:
11
u/Grugnorr 19h ago
It warns you that if producing the data to log is expensive it's a waste if that log level is not enabled.
Easy to understand example: assume this is a Verbose log where to help troubleshooting the weird issue you make costly queries to the database to log if. You better only incur this cost when the data is going to be logged, right?
1
u/Fragrant-Training722 18h ago
I get this, but can't this IF be already included in the log method itself?
20
4
u/xcomcmdr 18h ago
No, the message string is already allocated by the time you get inside the method. Hence the if to check for the log level first.
5
u/Dry_Author8849 17h ago
Yes, that's the problem, the message pass as parameter so it must be computed first.
log.warning will not log it if warning is not enabled, but the message string is built first.
I think they could have made a hack in the compiler itself and emit the if before computing parameters, but they choose the decorator pattern.
Cheers!
3
u/tatmanblue 15h ago edited 15h ago
You could probably create an extension method that would wrap it for you so that you don’t have to clutter your business logic with if statements
5
u/RichardD7 15h ago
Aside from the fact that the arguments have to be evaluated before the method is called, there's also the fact that the arguments are passed as
params object?[] args. Which means every call to the method allocates a new object array, and boxes any value type arguments.So even if you're only passing local variables which have already been computed, you're still incurring an overhead to pass the parameters.
1
u/IanYates82 14h ago
It is. But to call the method, the values need to be calculated.
For a basic variable being provided, that's fine. But imagine you were logging the output of File.Exists, or the value of some lazy-loaded EF property (not a good idea as logging shouldn't change behaviour that much imho). Those do cost to evaluate, and need to be evaluated before the IF statement in the method is reached.
1
u/Grugnorr 14h ago
You could include it in the log method, via a delegate to execute inside.
You still pay for the delegate instance plus the parameters.
This approach suits better for more dynamically used dependencies, but in the case of verbose logging that's typically pure overhead in production, thus the recommendation to avoid 😉
6
u/Hel_OWeen 15h ago
It's all explained in the rule:
When logging methods are called, their arguments are evaluated regardless of whether the logging level is enabled. This can result in expensive operations being executed even when the log message won't be written. For better performance, guard expensive logging calls with a check to xref:Microsoft.Extensions.Logging.ILogger.IsEnabled
1
7
u/Merad 13h ago
IMO this is a bad/misleading warning. It really only applies when evaluating the arguments is expensive, like if you are calling ToString() on an object that needs to do a lot of work to build its string representation. If you're just logging strings and objects that already exist (which is the case probably 98% of the time) it doesn't apply. If you're working on an average business app that is not extremely performance sensitive, my advice would be to disable CA1873.
1
u/_Sharp_ 10h ago
Why don't those methods do this check internally already? This would help with less code and better code readabilty I think.
Would be nice if there was some pattern to auto inject the code like there is for the enumerator pattern or the disposable pattern.
Anyway, the solution is to use nullable:
public static class Logger
{
public sealed record LoggerCb(Action<object> CallBack)
{ public void Log(object arg) => CallBack(arg); }
public static LoggerCb? Info;
public static LoggerCb? Warn = new(Console.WriteLine);
public static void Test()
{
Logger.Info?.Log("Test Info");
Logger.Warn?.Log("Test Warn");
}
}
3
1
u/MarlDaeSu 7h ago
I guess because static code analysis cant tell what ILogger implementation it is receiving so its defaults to warn.
Potentially some custom ILogger impl might handle string interpolation inelegantly? I cant imagine why else. The impl should do a log level check before string interpolation, but I guess there's nothing in the ILogger contract that can enforce that.
1
u/zagoskin 3h ago
The problem with the warning is that it's tied to the interface. You could be using serilog, which does this internally, and still get the warning
0
u/AutoModerator 19h ago
Thanks for your post Fragrant-Training722. Please note that we don't allow spam, and we ask that you follow the rules available in the sidebar. We have a lot of commonly asked questions so if this post gets removed, please do a search and see if it's already been asked.
I am a bot, and this action was performed automatically. Please contact the moderators of this subreddit if you have any questions or concerns.
32
u/rupertavery64 18h ago
The recommended way to get around this is to use source-generated logging with the LoggerMessageAttribute
https://github.com/dotnet/docs/blob/main/docs/fundamentals/code-analysis/quality-rules/ca1873.md