Suppress logging checks in query when not required, caching for 1 second

[roji]

If no logging occurs (no interceptor, MS.Extensions.Logging, DiagnosticSource...), cache this fact and skip logging entirely for 1 second. This allows DiagnosticListeners and MS.Extensions.Logging to be modified at runtime without paying the price of checking at every single query execution.

This brings our Fortunes RPS up from 82167 to 91208, an 11% increase.

An alternative approach is a global flag to disable (perf-sensitive?) logging. I experimented with commenting out logging in these paths, and the difference seem very small; small enough IMHO to prefer this, which benefits all users without a special opt-in.

This PR is just a prototype - if the approach is OK I'll complete it. This is based on #24207, look at the last commit only.

[roji]

Note: just avoiding Guid.NewGuid (command correlation ID) yielded a ~3% RPS improvement (BDN measures this method, which does native interop, at 800ns).

[adamsitnik]

just avoiding Guid.NewGuid (command correlation ID) yielded a ~3% RPS improvement

FWIW Guid.NewGuid is known to be 10 times slower on Linux compared to Windows: dotnet/runtime#13628 but this is mostly caused by the fact that random numbers generation on Linux is so slow

[ErikEJ]

Wauw - what RPS rate is Dapper at?

[roji]

Thanks @adamsitnik, good to get confirmation on Guid.NewGuid...

@ErikEJ Dapper is at 93453, you can follow progress at: #23611 (comment)

[ajcvickers]

@roji Doses this mean that if I have logging set for a single event that only happens occasionally when a certain error occurs, then I will have very little chance of seeing that event in the log because it will likely happen sometime within the 1 second cache window?

[roji]

Errors are exempt from this - they're always logged (there's also no perf overhead for that).

Basically, for high-perf non-error events only, if we try to log and discover nothing was set up (diagnostics listener, logger, interceptor..), we abstain from logging again for one second. This means we support changing of logging config at runtime (e.g. adding a diagnostics listener), but users may have to wait for up to 1 second for that to take effect.

[roji]

@ajcvickers was there a specific reason to use StopWatch instead of just subtracting timestamps, given that we already took the starting timestamp? Was this a concern with increased timer precision or something?

[ajcvickers]

@roji I would very much like to hear what the rest of the team think about this. :-) @dotnet/efteam

[roji]

@ajcvickers that looks like a very euphemistic comment to me 🔥🔥🔥

But yeah, let's discuss. We can always fall back to some sort of global flag opt-out or something.

[ajcvickers]

@roji I'm trying hard not to state my opinions strongly before others get a chance to speak. :-)

[roji]

This certainly ended up being more work than expected... @AndriySvyryd @ajcvickers

This bumps our TechEmpower Fotunes RPS from 82,892 to 91,266, roughly 10%.

[ghost]

Hello @roji!

Because this pull request has the auto-merge label, I will be glad to assist with helping to merge this pull request once all check-in policies pass.

p.s. you can customize the way I help with merging this pull request, such as holding this pull request until a specific person approves. Simply @mention me (@msftbot) and give me an instruction to get started! Learn more here.

[ghost]

Apologies, while this PR appears ready to be merged, I've been configured to only merge when all checks have explicitly passed. The following integrations have not reported any progress on their checks and are blocking auto-merge:

1. Azure Pipelines

These integrations are possibly never going to report a check, and unblocking auto-merge likely requires a human being to update my configuration to exempt these integrations from requiring a passing check.

Give feedback on this

From the bot dev team

We've tried to tune the bot such that it posts a comment like this only when auto-merge is blocked for exceptional, non-intuitive reasons. When the bot's auto-merge capability is properly configured, auto-merge should operate as you would intuitively expect and you should not see any spurious comments.

Please reach out to us at [email protected] to provide feedback if you believe you're seeing this comment appear spuriously. Please note that we usually are unable to update your bot configuration on your team's behalf, but we're happy to help you identify your bot admin.

[lauxjpn]

The solution we ended up implementing was to check whether any sort of logging or interception is enabled, and if not, suppress logging for that event for 1 second by default. This improved benchmark throughput by around 7% – very close to the global flag solution – while at the same time bringing the perf benefit to all EF Core users, without an opt-in. If, say, a DiagnosticListener is registered at some point during program execution, it may take up to a > second for events to start appearing there; that seemed like a very reasonable trade-off for the speed-up.

It seems a bit of an odd choice to me, that the non-deterministic behavior is the default for a logging/event infrastructure. Doesn't this introduce a whole new level of complexity/uncertainty, because it can give you back inaccurate/wrong results now at will?
Also, the infrastructure might not just be used for logging (deterministic or not), but also for executing code in general that is supposed to run in a deterministic fashion.
A big issue resulting from this change is, that bugs due to this breaking change will be very hard (costly) for users to analyze an fix, because of their non-deterministic nature and because this change does not throw.
(Or is the whole usage scenario considered too obscure to actually matter in practice?)

With the current implementation, does calling DbContextOptionsBuilder.LoggingConfigCacheTime(TimeSpan.Zero) effectively opt out of the new non-deterministic behavior and makes it deterministic again?

[roji]

@lauxjpn we discussed this at length internally.

The only non-determinism here is when your logging/DiagnosticListener/interception configuration changes as the program is already running. However, in the general case there's already a race condition between the code (or user) changing the configuration and the running program; for example, there already isn't any guarantee exactly when a new DiagnosticListener starts getting events as you're registering it.

Since in general, we assume that runtime changes to logging/DiagnosticListener/interception are rare, it seemed more useful to users to have EF run faster by default, and to provide an opt-out if needed.

With the current implementation, does calling DbContextOptionsBuilder.LoggingConfigCacheTime(TimeSpan.Zero) effectively opt out of the new non-deterministic behavior and makes it deterministic again?

Yes.

[lauxjpn]

The only non-determinism here is when your logging/DiagnosticListener/interception configuration changes as the program is already running. However, in the general case there's already a race condition between the code (or user) changing the configuration and the running program; for example, there already isn't any guarantee exactly when a new DiagnosticListener starts getting events as you're registering it.

Yeah, so it is considered too obscure then. It is possible to do this deterministically without race condition (which can be somewhere between simple and hard, depending on the app), but I guess its fair that the scenario is not a very common one.

Just thought it was weird, since making this opt-in would definitely not break anyone's code and not matter to 99% of users in regards to performance anyhow, for which the very high throughput scenario is just not a concern. The few users that care about this level of performance, would likely do some research and actually read the appropriate docs about it, and thereby learn about the switch to opt-in.

Anyway, it seems that the decision has already been made.

BTW, I like the general EF Core concept of letting users control the impact of expensive features. Makes it much more competitive with micro ORMs despite being feature rich.