Add CA1873: Avoid potentially expensive logging #7290

mpidash · 2024-04-15T01:49:18Z


Rule ID	CA1873
Title	Avoid potentially expensive logging
Message	Evaluation of this argument may be expensive and unnecessary if logging is disabled
Description	In many situations, logging is disabled or set to a log level that results in an unnecessary evaluation for this argument.
Category	Performance
Severity	Suggestion

This analyzer detects

calls to ILogger.Log,
calls to extension methods in Microsoft.Extensions.Logging.LoggerExtensions and
calls to methods decorated with [LoggerMessage]

and flags them if they evaluate expensive arguments without checking if logging is enabled with ILogger.IsEnabled.

There are 12 findings in dotnet/runtime (8 of them in Microsoft.Extensions.Logging.Abstractions which will probably disable this warning), 157 findings in dotnet/roslyn and 497 in dotnet/aspnetcore (including testing code).
I skimmed through them and could not find any false positives.

This analyzer detects calls to 'ILogger.Log', extension methods in 'Microsoft.Extensions.Logging.LoggerExtensions' and methods decorated with '[LoggerMessage]'. It then checks if they evaluate expensive arguments without checking if logging is enabled with 'ILogger.IsEnabled'.

mpidash · 2024-04-15T01:55:51Z

...ers/Core/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLogging.cs

+                    // Check the argument value after conversions to prevent noise (e.g. implicit conversions from null or from int to EventId).
+                    if (IsPotentiallyExpensive(argument.Value.WalkDownConversion()))


This is a bit of a deviation from the description in the runtime issue, but without this, there would be a lot of noise.
The following lines would be flagged:

void M(ILogger logger, EventId eventId, Exception exception, Func<object, Exception, string> formatter) { logger.Log(LogLevel.Trace, eventId, null, exception, formatter); logger.Log(LogLevel.Trace, 0, "literal", exception, formatter); }

mpidash · 2024-04-15T02:00:04Z

...ers/Core/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLogging.cs

+                // Implicit params array creation is treated as not expensive. This would otherwise cause a lot of noise.
+                or IArrayCreationOperation { IsImplicit: true, Initializer.ElementValues.IsEmpty: true }


Same here, without this, all log calls that take a params array would always be flagged, even if they do not capture anything, e.g.:

void M(ILogger logger) { logger.LogInformation("literal"); }

mpidash · 2024-04-15T02:04:10Z

...ers/Core/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLogging.cs

+                var conditionInvocations = conditional.Condition
+                    .DescendantsAndSelf()
+                    .OfType<IInvocationOperation>();
+
+                // Check each invocation in the condition to see if it is a valid guard invocation, i.e. same instance and same log level.
+                // This is not perfect (e.g. 'if (logger.IsEnabled(LogLevel.Debug) || true)' is treated as guarded), but should be good enough to prevent false positives.
+                if (conditionInvocations.Any(IsValidIsEnabledGuardInvocation))
+                {
+                    return true;
+                }


As stated in the comment, this is not perfect, but should be good enough to prevent false positives.

mpidash · 2024-04-15T02:05:36Z

...ers/Core/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLogging.cs

+                    return AreInvocationsOnSameInstance(logInvocation, invocation) && IsSameLogLevel(invocation.Arguments[0]);
+                }
+
+                static bool AreInvocationsOnSameInstance(IInvocationOperation invocation1, IInvocationOperation invocation2)


A variation of this is used in other analyzers. I think this could be a good candidate for another extension method.

mpidash · 2024-04-15T02:08:32Z

...sts/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLoggingTests.cs

+        [Fact]
+        public async Task WrongLogLevelGuardedWorkInLog_ReportsDiagnostic_CS()
+        {
+            string source = """
+                using System;
+                using Microsoft.Extensions.Logging;
+
+                class C
+                {
+                    void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter)
+                    {
+                        if (logger.IsEnabled(LogLevel.Critical))
+                            logger.Log(LogLevel.Trace, eventId, [|ExpensiveMethodCall()|], exception, formatter);


I was wondering if we should report another diagnostic if the log level does not match, as this is most likely a bug.

mpidash · 2024-04-15T02:09:34Z

...sts/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLoggingTests.cs

+        [Fact]
+        public async Task WrongInstanceGuardedWorkInLog_ReportsDiagnostic_CS()
+        {
+            string source = """
+                using System;
+                using Microsoft.Extensions.Logging;
+
+                class C
+                {
+                    private ILogger _otherLogger;
+
+                    void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter)
+                    {
+                        if (_otherLogger.IsEnabled(LogLevel.Trace))
+                            logger.Log(LogLevel.Trace, eventId, [|ExpensiveMethodCall()|], exception, formatter);


Another candidate for a diagnostic: Checking the wrong logger instance.

mpidash · 2024-04-15T02:11:24Z

cc @stephentoub @Youssef1313 (thanks for providing the prototype 👍)

codecov · 2024-04-15T02:14:29Z

Codecov Report

Attention: Patch coverage is 84.32432% with 29 lines in your changes missing coverage. Please review.

Project coverage is 96.52%. Comparing base (8d4f432) to head (86a52c0).

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #7290      +/-   ##
==========================================
+ Coverage   96.50%   96.52%   +0.02%     
==========================================
  Files        1443     1445       +2     
  Lines      346376   349503    +3127     
  Branches    11387    11427      +40     
==========================================
+ Hits       334255   337352    +3097     
- Misses       9239     9254      +15     
- Partials     2882     2897      +15

stephentoub · 2024-04-22T13:49:27Z

I skimmed through them and could not find any false positives.

ca1873-runtime.txt

Thanks. The LoggerExtensions.cs ones are all false positives in that we'll want to suppress them, but that's also effectively the implementation of logging rather than consumption of logging, and we frequently have to suppress rules in such implementations. The others for runtime look like valid diagnostics.

drewnoakes · 2024-07-24T03:34:10Z

...sts/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLoggingTests.cs

+                {
+                    void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter)
+                    {
+                        logger.Log(LogLevel.Debug, eventId, [|nameof(logger)|], exception, formatter);


Isn't nameof free at runtime?

IIRC I used the description from the runtime issue:

Analyzer would detect when "work" is being done in an argument call to an ILogger logging method. This basically boils down to anything other than a literal-expression, local-expression, parameter-expression, field-expression, property-expression, or indexer-expression (potentially recursively applied).

I think excluding the nameof expression is in the spirit of the rule (i.e. no work is done in the log call).

drewnoakes · 2024-07-24T03:35:26Z

...sts/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLoggingTests.cs

+                {
+                    void M(ILogger logger, EventId eventId, Exception exception, Func<int, Exception, string> formatter, int input)
+                    {
+                        logger.Log(LogLevel.Debug, eventId, [|input++|], exception, formatter);


In this case, wrapping the log call with a check would change behaviour. Maybe the increment is needed.

We could exclude postfix increment and decrement.

drewnoakes · 2024-07-24T03:35:48Z

...sts/Microsoft.NetCore.Analyzers/Performance/AvoidPotentiallyExpensiveCallWhenLoggingTests.cs

+                {
+                    void M(ILogger logger, EventId eventId, Exception exception, Func<int, Exception, string> formatter)
+                    {
+                        logger.Log(LogLevel.Debug, eventId, [|default|], exception, formatter);


Isn't default free at runtime?

Isn't default free at runtime?

For reference types.

For value types, it depends on the type. But it should, in general, be "free".

Right, I mean, there's no overhead in passing the value. It's just zeroed memory. I don't think it warrants a diagnostic.

Here's a sharplab.io showing default and nameof are both compile-time constant values.

private static void Foo(params object?[] objects) {} public static void M() { Foo(default(int), default(object), nameof(Foo)); }

...M() becomes...

object[] array = new object[3]; array[0] = 0; // don't set array[1] as it's already null array[2] = "Foo"; Foo(array);

For this code, value types will be boxed.

Wither being boxed or passed by value, big value types may be a problem.

I know you're not thinking of those, but they are out there.

If the original concern here was boxing (having that info in the diagnostic message, or at least in a comment would be helpful) then it should only apply to value types. I'd like to hear @mpidash's motivation here.

My motivation was the same as in #7290 (comment). I think we could also exclude default; there may be places where it is not 100% free, but the same could be argued for properties and we exclude those as well.

mpidash requested a review from a team as a code owner April 15, 2024 01:49

github-actions bot added the Community label Apr 15, 2024

mpidash commented Apr 15, 2024

View reviewed changes

Youssef1313 mentioned this pull request May 12, 2024

Initial prototype of AvoidPotentiallyExpensiveCallWhenLoggingAnalyzer #6643

Closed

Merge branch 'main' into issue-78402

fbf9763

mpidash closed this Jul 5, 2024

mpidash reopened this Jul 5, 2024

drewnoakes reviewed Jul 24, 2024

View reviewed changes

Merge branch 'main' into issue-78402

86a52c0

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add CA1873: Avoid potentially expensive logging #7290

Add CA1873: Avoid potentially expensive logging #7290

mpidash commented Apr 15, 2024

mpidash Apr 15, 2024

mpidash Apr 15, 2024

mpidash Apr 15, 2024

mpidash Apr 15, 2024

mpidash Apr 15, 2024

mpidash Apr 15, 2024

mpidash commented Apr 15, 2024

codecov bot commented Apr 15, 2024 •

edited

Loading

stephentoub commented Apr 22, 2024

drewnoakes Jul 24, 2024

mpidash Aug 21, 2024

drewnoakes Jul 24, 2024

mpidash Aug 21, 2024

drewnoakes Jul 24, 2024

paulomorgado Jul 24, 2024

drewnoakes Jul 24, 2024

paulomorgado Jul 24, 2024

drewnoakes Jul 24, 2024

mpidash Aug 21, 2024

		// Check the argument value after conversions to prevent noise (e.g. implicit conversions from null or from int to EventId).
		if (IsPotentiallyExpensive(argument.Value.WalkDownConversion()))

		// Implicit params array creation is treated as not expensive. This would otherwise cause a lot of noise.
		or IArrayCreationOperation { IsImplicit: true, Initializer.ElementValues.IsEmpty: true }

Add CA1873: Avoid potentially expensive logging #7290

Are you sure you want to change the base?

Add CA1873: Avoid potentially expensive logging #7290

Conversation

mpidash commented Apr 15, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mpidash commented Apr 15, 2024

codecov bot commented Apr 15, 2024 • edited Loading

Codecov Report

stephentoub commented Apr 22, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

codecov bot commented Apr 15, 2024 •

edited

Loading