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

Size based EventId LogEventProperty cache #260

Merged
merged 10 commits into from
Nov 15, 2024

Conversation

AndreReise
Copy link

Address #259

The LogEventConstructionBenchmark results

BenchmarkDotNet v0.13.10, Windows 10 (10.0.19045.5073/22H2/2022Update)
Intel Core i5-10300H CPU 2.50GHz, 1 CPU, 8 logical and 4 physical cores
.NET SDK 8.0.100
[Host] : .NET 8.0.10 (8.0.1024.46610), X64 RyuJIT AVX2
DefaultJob : .NET 8.0.10 (8.0.1024.46610), X64 RyuJIT AVX2

Before:

Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
Native 207.0 ns 4.18 ns 4.29 ns 1.00 0.00 0.0706 296 B 1.00
NoId 296.4 ns 3.47 ns 3.07 ns 1.43 0.04 0.1106 464 B 1.57
LowNumbered 381.9 ns 5.28 ns 4.68 ns 1.84 0.05 0.1740 728 B 2.46
HighNumbered 394.6 ns 7.43 ns 13.76 ns 1.97 0.06 0.1931 808 B 2.73

After:

Method Mean Error StdDev Ratio RatioSD Gen0 Allocated Alloc Ratio
Native 209.7 ns 4.00 ns 3.75 ns 1.00 0.00 0.0706 296 B 1.00
NoId 296.4 ns 5.75 ns 5.10 ns 1.41 0.04 0.1106 464 B 1.57
LowNumbered 348.0 ns 6.91 ns 6.47 ns 1.66 0.04 0.1335 560 B 1.89
HighNumbered 332.4 ns 3.61 ns 3.20 ns 1.59 0.03 0.1335 560 B 1.89

Copy link
Member

@nblumhardt nblumhardt 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 looking into this! Had a few comments, let me know if you need any more info. Cheers!


cachedProperty = CreateCore(in eventKey);

if (count < _maxCapacity)
Copy link
Member

Choose a reason for hiding this comment

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

Applications log a lot of things during start-up that they never log again. Perhaps clearing the cache when it reaches the size limit, and then (lazily) repopulating it, is worth considering, here? Bumping the cache size up to e.g. 256 items would help to avoid degenerate cases.

Copy link
Author

Choose a reason for hiding this comment

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

I think we could consider making this cache shared (as a static class) among all loggers. Since ConcurrentDictionary is lock-free on reads, I believe this approach could perform as well as a per-logger cache.

Perhaps clearing the cache when it reaches the size limit

This problem can be addressed by choosing the correct max-cached-items parameter. Speculatively, the total set of application and library event IDs can typically fit into a single cache. A maximum of 1024 items seems reasonable to me.

Implementing an LRU cache could help save some memory. However, this approach might introduce more lock contention, potentially impacting performance.

So, I'd like to suggest using the approach the Microsoft team implemented for caching in FormattedLogValues.

Copy link
Author

Choose a reason for hiding this comment

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

Almost everything exactly the same as in FormattedLogValues source code.

private const int MaxCachedProperties = 1024;

private static readonly ConcurrentDictionary<EventKey, LogEventProperty> s_propertyCache = new ();
private static int s_count;

public static LogEventProperty GetOrCreateProperty(in EventId eventId)
{
    var eventKey = new EventKey(eventId);

    LogEventProperty? property;

    if (s_count >= MaxCachedProperties)
    {
        if (!s_propertyCache.TryGetValue(eventKey, out property))
        {
            property = CreateCore(in eventKey);
        }
    }
    else
    {
        property = s_propertyCache.GetOrAdd(
            eventKey,
            static key =>
            {
                Interlocked.Increment(ref s_count);

                return CreateCore(in key);
            });
    }

    return property;
}

Actually, the factory in GetOrAdd might be called multiple times. I don't think this is a problem, as total correctness is not required in this case.

@AndreReise AndreReise requested a review from nblumhardt November 4, 2024 15:21
Copy link
Member

@nblumhardt nblumhardt left a comment

Choose a reason for hiding this comment

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

Looks great, thanks for following up on this. Apologies for the slow review, I'm stuck in the middle of a busy few weeks 😅

using Microsoft.Extensions.Logging;
using Serilog.Events;

static class EventIdPropertyCache
Copy link
Member

Choose a reason for hiding this comment

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

Might be best to make this a non-static class and declare an instance in a static variable, the same way CachingMessageTemplateParser is used; in the long run, both of these caches should probably be scoped to the logger factory instead of being static, so this organization will help towards that.

{
const int MaxCachedProperties = 1024;

static readonly ConcurrentDictionary<EventKey, LogEventProperty> s_propertyCache = new();
Copy link
Member

Choose a reason for hiding this comment

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

Nit: static field names in this codebase use PascalCase.

static readonly ConcurrentDictionary<EventKey, LogEventProperty> s_propertyCache = new();
static int s_count;

public static LogEventProperty GetOrCreateProperty(in EventId eventId)
Copy link
Member

Choose a reason for hiding this comment

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

With the class converted to non-static, it'd be possible to test that this method returns the same instance (ReferenceEquals()) for the same eventId properties, and different instances when different event ids are passed/when the cache is full.


static class EventIdPropertyCache
{
const int MaxCachedProperties = 1024;
Copy link
Member

Choose a reason for hiding this comment

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

Passing this as a constructor arg (non-static class) would make testing behavior around cache limits clearer/easier.

@nblumhardt nblumhardt merged commit 5e1527d into serilog:dev Nov 15, 2024
1 check passed
@nblumhardt
Copy link
Member

Looks great; thanks @AndreReise!

@nblumhardt nblumhardt mentioned this pull request Dec 6, 2024
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.

2 participants