Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add CA1873: Avoid potentially expensive logging #7290

Open
wants to merge 3 commits into
base: main
Choose a base branch
from

Conversation

mpidash
Copy link
Contributor

@mpidash mpidash commented Apr 15, 2024

Fixes dotnet/runtime#78402.

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 mpidash requested a review from a team as a code owner April 15, 2024 01:49
Comment on lines +92 to +93
// 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()))
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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);
}

Comment on lines +111 to +112
// 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 }
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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");
}

Comment on lines +275 to +284
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;
}
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

return AreInvocationsOnSameInstance(logInvocation, invocation) && IsSameLogLevel(invocation.Arguments[0]);
}

static bool AreInvocationsOnSameInstance(IInvocationOperation invocation1, IInvocationOperation invocation2)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Comment on lines +1584 to +1596
[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);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Comment on lines +1806 to +1820
[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);
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

@mpidash
Copy link
Contributor Author

mpidash commented Apr 15, 2024

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

Copy link

codecov bot commented Apr 15, 2024

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
Copy link
Member

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.

@mpidash mpidash closed this Jul 5, 2024
@mpidash mpidash reopened this Jul 5, 2024
{
void M(ILogger logger, EventId eventId, Exception exception, Func<string, Exception, string> formatter)
{
logger.Log(LogLevel.Debug, eventId, [|nameof(logger)|], exception, formatter);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't nameof free at runtime?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We could exclude postfix increment and decrement.

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

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't default free at runtime?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't default free at runtime?

For reference types.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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);

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

[Analyzer] Usage of ToString in logging source generator method call sites
4 participants