A lot of useless log.Debug in Ocelot

[RaynaldM]

We're looking to speed up Ocelot a bit, and gain a few extra requests/second.
Using the benchmark, we ran a small test on DownstreamRouteFinderMiddlewareBenchmarks
In DownstreamRouteFinderMiddleware, we put the log.Debug in #if DEBUG like this:

       public async Task Invoke(HttpContext httpContext)
        {
            var upstreamUrlPath = httpContext.Request.Path.ToString();

            var upstreamQueryString = httpContext.Request.QueryString.ToString();

            var hostHeader = httpContext.Request.Headers["Host"].ToString();
            var upstreamHost = hostHeader.Contains(':')
                ? hostHeader.Split(':')[0]
                : hostHeader;

#if DEBUG
            Logger.LogDebug($"Upstream url path is {upstreamUrlPath}");
#endif

            var internalConfiguration = httpContext.Items.IInternalConfiguration();

            var provider = _factory.Get(internalConfiguration);

            var response = provider.Get(upstreamUrlPath, upstreamQueryString, httpContext.Request.Method, internalConfiguration, upstreamHost);

            if (response.IsError)
            {
                Logger.LogWarning($"{MiddlewareName} setting pipeline errors. IDownstreamRouteFinder returned {response.Errors.ToErrorString()}");

                httpContext.Items.UpsertErrors(response.Errors);
                return;
            }

#if DEBUG
            var downstreamPathTemplates = string.Join(", ", response.Data.Route.DownstreamRoute.Select(r => r.DownstreamPathTemplate.Value));
            Logger.LogDebug($"downstream templates are {downstreamPathTemplates}");
#endif

            // why set both of these on HttpContext
            httpContext.Items.UpsertTemplatePlaceholderNameAndValues(response.Data.TemplatePlaceholderNameAndValues);

            httpContext.Items.UpsertDownstreamRoute(response.Data);

            await _next.Invoke(httpContext);
        }

and the result was surprising:

With log.Debug

|   Method |     Mean |     Error |    StdDev |    StdErr |      Min |       Q1 |   Median |       Q3 |      Max |      Op/s | Ratio |  Gen 0 | Allocated |
|--------- |---------:|----------:|----------:|----------:|---------:|---------:|---------:|---------:|---------:|----------:|------:|-------:|----------:|
| Baseline | 1.232 us | 0.1523 us | 0.0236 us | 0.0118 us | 1.206 us | 1.217 us | 1.232 us | 1.248 us | 1.258 us | 811,506.6 |  1.00 | 0.3033 |      4 KB |

without

|   Method |     Mean |    Error |  StdDev |  StdErr |      Min |       Q1 |   Median |       Q3 |      Max |        Op/s | Ratio |  Gen 0 | Allocated |
|--------- |---------:|---------:|--------:|--------:|---------:|---------:|---------:|---------:|---------:|------------:|------:|-------:|----------:|
| Baseline | 890.6 ns | 28.16 ns | 4.36 ns | 2.18 ns | 884.2 ns | 889.7 ns | 892.4 ns | 893.3 ns | 893.4 ns | 1,122,855.0 |  1.00 | 0.2213 |      3 KB |

We gained around 300 request/s, i.e. a 38% improvement - not bad, eh?

I wonder if we couldn't do the same for others, or even all of them.

What do you think?

[raman-m]

Ray, when you said: "With LogDebug", did you mean in debug session enabled?

Yes, it is right direction...
Also, try to change logging severity in launchSettings.json and/or appsettings.json (aka LogLevel property) from Debug to Error/Warning, and you will get another surprising results! 🥳 😉

[raman-m]

I never thought I'd start such a debate 😄
We're talking about 28 "logDebugs" in Ocelot (and related projects).

If you agree, we can easily make a PR where all logdebugs will be in "#if DEBUG" and won't even be compiled in Release mode.

@RaynaldM
I totally agree. I have no objections to wrap LogDebug by preprocessor directive.

[raman-m]

@RaynaldM I think a wrapper method would be the wise choice, then it's centralized? If you want, I can prepare the PR?

@ggnaegi
That's perfect idea to encapsulate prepossessor directive inside of LogDebug implementation. I like it!
For string interpolation vs data we can use Lazy<string> value getter.

But Func<string> delegate parameter is better. Sounds good?
Instead of Logger.LogDebug($"Upstream url path is {upstreamUrlPath}"); where interpolation & writing being performed,
...we could write like: Logger.LogDebug(() => $"Upstream url path is {upstreamUrlPath}"); via anonymous delegate object to invoke it only in Debug mode. So, everything goes to encapsulation, and nothing executed until DEBUG mode.

[raman-m]

@ggnaegi I totally agree with you, we have to use all the standard resources at our disposal, and we'll have to talk about RateLimiter... one day 😄 .

@RaynaldM Next design surprise by Rate Limiter? I have a strong feeling that someone at Microsoft just thieve Ocelot ideas... 😏
It is OK to discuss. But open new idea discussion thread please!

[ggnaegi]

@raman-m Oct 17

Yes that's exactly what I want to do, super optimization 😅

[RaynaldM]

why complicate things? these "logdebugs" have been around for a long time, and are useless for production purposes (unless you want to fill up a lot of useless log files), they're just for debugging, and I repeat, there are only 28 "LogDebug" in the entire source code.

A simple Search/Replace and you're done.
If everyone agrees, of course 😄 .

[raman-m]

@RaynaldM wrote
A simple Search/Replace and you're done.
If everyone agrees, of course 😄

I agree not removing, but I do agree on wrapping by preprocessor directive.
I have no time for that. Maybe @ggnaegi will prepare a PR...

@RaynaldM and @ggnaegi Have we reached a consensus? Will we turn this topic into an issue?

[ggnaegi]

@raman-m yes, I will be on it later today.

[raman-m]

@RaynaldM Please, open issue by magic button Create issue from discussion So, you'll be an author.

[raman-m]

The idea has been released by #1808