#1744 Avoid calls to 'Logger.Log' if LogLevel not enabled in appsettings.json

[ggnaegi]

Closes #1744

• A lot of useless log.Debug in Ocelot #1744

Changing string parameter of IOcelotLogger methods to Func<string>, modifying AspDotNetLogger.cs, only one main method and verifying if LogLevel is enabled. If log level isn't enabled, then return.

Proposed Changes

• Using Func<string> instead of string as parameter for log methods, avoiding unneeded string operations
• Checking if the LogLevel is enabled before 1) Calling ILogger.Log method; 2) calling Func<string>.Invoke().
• Code refactoring, only one method for Log writing in AspDotNetLogger.cs

private void WriteLog(LogLevel logLevel, Func<string> messageFactory, Exception exception = null)
{
    if (!_logger.IsEnabled(logLevel))
    {
        return;
    }

    var requestId = GetOcelotRequestId();
    var previousRequestId = GetOcelotPreviousRequestId();

    var state = $"requestId: {requestId}, previousRequestId: {previousRequestId}, message: {messageFactory.Invoke()}";

    _logger.Log(logLevel, default, state, exception, _func);
}

Benchmarks:

@raman-m @RaynaldM
Ok, after the refactoring, I realized that the benchmark, per design, has no log level defined. If I change the condition to

if (_logger.IsEnabled(logLevel))
        {
            throw new Exception("min si c'est génial");
        }

then it will run without throwing exceptions. It means IsEnabled is never true there. Ok, since I know that, and I have a wonderful unique wrapper method, I can get the the benchmarks values nearly without any logs activities.

Figure 1: Benchmark with empty WriteLog Wrapper method

Now, let's put back the new WriteLog method implementation. Performance is not as good as no logs activities at all, but the performance is still great.

Figure 2: Benchmark with new WriteLog Wrapper method

We can now try to log everything - at least call the log method

Figure 3: Log everything

And a final check, with the current develop branch

Figure 4: Current develop branch benchmark

As you can see, we have similar results for 3 and 4.

Discussion

• A lot of useless log.Debug in Ocelot #1736

[raman-m]

I do not approve this time. Where are the tests?
My concerns:

• Removing old signature methods is wrong until we'll find a solution to recognize string constants and string building
• No applied fix by @RaynaldM using #if DEBUG directive, which is main goal
• No unit tests for refactored WriteLog method, and there are no acceptance tests for the feature which fixes the case when LogLevel isn't enabled in appsettings.json

[ggnaegi]

I do not approve this time. Where are the tests? My concerns:

• Removing old signature methods is wrong until we'll find a solution to recognize string constants and string building
• No applied fix by @RaynaldM using #if DEBUG directive, which is main goal

We can keep the old signature methods, you're right, if it's a string constant, the factory is useless. We would aswell keep the backward compatibility.

[raman-m]

Gui,
Could you explain me Benchmarks results please?
Do we need to compare Median values, right?
I see that Ray's approach improves performance decreasing value by ~200 nanoseconds, from 1300 down to 1000.
But your design approach decreased the value in 2+ times, down to ~550 nanoseconds from ~1300 nanoseconds.
This is the perfect result! 🎉 Strong argument to use factory methods! 👍 😍

[raman-m]

From screenshots I didn't get it what benchmarks did you run?
Have you prepared special benchmark classes or used old ones?
How to run benchmarks locally?

[raman-m]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong?
We need to write a few acceptance tests... Adding this point to code review results...

[raman-m]

@ggnaegi Gui, let me focus on minor release for documentation... I've reviewed this PR, and I'll get back to you after the docs release... So, I'll be silent from now...

[ggnaegi]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong? We need to write a few acceptance tests... Adding this point to code review results...

Yes, I will add the test cases.

[ggnaegi]

Oh, and I've missed one thing in code review... You haven't tested the case when LogLevel is unknown to prove that optimization and the feature works in real, am I wrong? We need to write a few acceptance tests... Adding this point to code review results...

Same tests as @RaynaldM, you can start them locally from test/Ocelot.Benchmarks. I will provide a new Benchmark for the request mapper. It's on going...

[ggnaegi]

@raman-m I think, the code is now ready for review, I have added several unit tests - verifying if invoke is called, verifying if log has been called - and acceptance tests - verifying that the log level corresponds to the appsettings.json -

[raman-m]

Long code requires more improvement.
Thank you for writing tests! I will review maybe later. Try to compress them and use DRY approach: more small helpers.

And I will run benchmarks later too...
I have a concern about benchmarks: Why do you test Serilog injected implementation? In my opinion, we need to test standard MS ASP.NET logger implementations first.

[ggnaegi]

Long code requires more improvement.
Thank you for writing tests! I will review maybe later. Try to compress them and use DRY approach: more small helpers.

And I will run benchmarks later too...
I have a concern about benchmarks: Why do you test Serilog injected implementation? In my opinion, we need to test standard MS ASP.NET logger implementations first.

It's the case in the unit tests. I'm using serilog in the acceptance tests. I could have created an In memory logger though...

[raman-m]

@ggnaegi commented on Oct 28

Could we run tests for different loggers like Microsoft, Serilog etc.?

[ggnaegi]

@ggnaegi commented on Oct 28

Could we run tests for different loggers like Microsoft, Serilog etc.?

Yes, but that's again quite a bit of work...

[ggnaegi]

@raman-m changes analyzed and code updated. You can re-review

[raman-m]

This feature should be included in October's release.
Going to review once again...

[raman-m]

@ggnaegi Please, check auto-merge results after the last merging of develop!

[ggnaegi]

Hello @raman-m, should be fine

[raman-m]

Code review, 2nd round is over! ✔️

Before fixing issues, it is better to rebase feature branch onto develop.
Sometimes I saw strange diff without actual changes. Maybe they appear after my merging of develop in f1f43bc by GitHub auto-merger. Sorry! Such huge PRs should be rebased each time.

Thanks for the great code quality! 💪

[raman-m]

Could you rebase the feature branch onto ThreeMammals:develop please?
OR
Could you sync your fork to update develop please?
And, rebase the feature branch onto develop please.

[ggnaegi]

@raman-m Rebase done

[raman-m]

Ready for delivery! ✅

Congrats, @ggnaegi ! 🥳