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

Phase one logger optimisations #2503

Merged
merged 5 commits into from
Nov 28, 2024
Merged

Conversation

stevejgordon
Copy link
Contributor

@stevejgordon stevejgordon commented Nov 27, 2024

This PR dramatically reduces the overhead of scoped logging, even for scenarios where the configured log level verbosity was low (e.g., Warning). The most critical improvement is caching scoped loggers within Spans, Traces, and Errors. We lose convenience in no longer having the span ID in the scope, but it's generally available from the Span argument.

Previously, a new ScopedLogger was created for every span and transaction, and a new ConditionalWeakTable was also allocated. Due to the use of Finalisers on the CWT, this had an even more significant GC impact. We now maintain a cache of scoped loggers (of which there are relatively few).

The ID creation for the Spans has been switched to ActivitySpanId.CreateRandom().ToString() from the MS diagnostics library, as this has been more heavily optimised than our original version and achieves the same goal.

In Tracer.End(), we used an Assertion with a large interpolated string. This was being interpolated for each transaction as the Assertion path was enabled. However, the condition we assert is generally not met. Therefore, we now check this manually to only create the message if we are in an invalid state.

I've also switched two structs to record structs, as these were used as keys in dictionaries and ended up being boxed due to a lack of IEquality implementations.

These are phase one of optimisations for the logging implementation and address the general production scenario of using a less verbose log level.

Profiling

Profiling was achieved using a .NET 9 ASP.NET Core minimal API project with 20 concurrent connections and 100,000 requests.

Before Memory Profile
image

After Memory Profile
image

Before Top Retained
image

After Top Retained
image

Closes #2500

- Cache scoped loggers to avoid allocations per span, transaction and error
@stevejgordon stevejgordon force-pushed the phase-one-logger-optimisations branch from edcaf70 to 02c433f Compare November 27, 2024 15:02
@stevejgordon stevejgordon marked this pull request as ready for review November 27, 2024 15:56
Copy link
Contributor

@gregkalapos gregkalapos left a comment

Choose a reason for hiding this comment

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

Overall I totally agree with the direction. 👍

Below one thing about replacing the ?. notation to check log levels. Less relevant from the allocation's perspective, but I think it'd be still worth keeping that.

src/Elastic.Apm/Logging/IApmLoggingExtensions.cs Outdated Show resolved Hide resolved
@ArminShoeibi
Copy link

There is a gotcha here, we should use lock like dotnet framework for AddOrUpdate

Formatters.AddOrUpdate(message, formatter);

image

for more details:

https://learn.microsoft.com/en-us/dotnet/api/system.collections.concurrent.concurrentdictionary-2.addorupdate?view=net-9.0

@stevejgordon
Copy link
Contributor Author

@ArminShoeibi Formatters is ConditionalWeakTable<string, LogValuesFormatter>. I need to review that, but I think it's okay here.

@ArminShoeibi
Copy link

@ArminShoeibi Formatters is ConditionalWeakTable<string, LogValuesFormatter>. I need to review that, but I think it's okay here.

My bad, it has a lock itself

https://github.com/dotnet/runtime/blob/1d1bf92fcf43aa6981804dc53c5174445069c9e4/src/libraries/System.Private.CoreLib/src/System/Runtime/CompilerServices/ConditionalWeakTable.cs#L126

@stevejgordon
Copy link
Contributor Author

No worries. It's hard to keep track!

@stevejgordon stevejgordon force-pushed the phase-one-logger-optimisations branch from 095cb52 to d98737d Compare November 28, 2024 08:16
@stevejgordon stevejgordon force-pushed the phase-one-logger-optimisations branch from d98737d to b30ad1b Compare November 28, 2024 08:24
@gregkalapos gregkalapos self-requested a review November 28, 2024 09:04
gregkalapos
gregkalapos previously approved these changes Nov 28, 2024
Copy link
Contributor

@gregkalapos gregkalapos left a comment

Choose a reason for hiding this comment

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

Thanks for the updates.

lgtm

@stevejgordon stevejgordon merged commit 1adae59 into main Nov 28, 2024
16 checks passed
@stevejgordon stevejgordon deleted the phase-one-logger-optimisations branch November 28, 2024 12:05
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Notable increase in memory usage from 1.25.x to 1.30.x
3 participants