Skip to content

Size based EventId LogEventProperty cache #260

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

Merged
merged 10 commits into from
Nov 15, 2024
Merged
Original file line number Diff line number Diff line change
@@ -0,0 +1,103 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.

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

internal sealed class EventIdPropertyCache
{
private readonly object _createLock = new();
private readonly int _maxCapacity;
private readonly Dictionary<EventKey, LogEventProperty> _propertyCache;

private int count;

public EventIdPropertyCache(int maxCapacity)
{
_maxCapacity = maxCapacity;
_propertyCache = new Dictionary<EventKey, LogEventProperty>(capacity: maxCapacity);
}

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

if (_propertyCache.TryGetValue(eventKey, out var cachedProperty))
{
return cachedProperty;
}

lock (_createLock)
{
// Double check under lock
if (_propertyCache.TryGetValue(eventKey, out cachedProperty))
{
return cachedProperty;
}

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
Contributor 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
Contributor 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.

{
_propertyCache[eventKey] = cachedProperty;
count++;
}

return cachedProperty;
}
}

private static LogEventProperty CreateCore(in EventKey eventKey)
{
var properties = new List<LogEventProperty>(2);

if (eventKey.Id != 0)
{
properties.Add(new LogEventProperty("Id", new ScalarValue(eventKey.Id)));
}

if (eventKey.Name != null)
{
properties.Add(new LogEventProperty("Name", new ScalarValue(eventKey.Name)));
}

return new LogEventProperty("EventId", new StructureValue(properties));
}

private readonly struct EventKey : IEquatable<EventKey>
{

public EventKey(EventId eventId)
{
Id = eventId.Id;
Name = eventId.Name;
}

public int Id { get; }

public string? Name { get; }

/// <inheritdoc />
public override int GetHashCode()
{
unchecked
{
var hashCode = 17;

hashCode = (hashCode * 397) ^ this.Id;
hashCode = (hashCode * 397) ^ (this.Name?.GetHashCode() ?? 0);

return hashCode;
}
}

/// <inheritdoc />
public bool Equals(EventKey other) => this.Id == other.Id && this.Name == other.Name;

/// <inheritdoc />
public override bool Equals(object? obj) => obj is EventKey other && Equals(other);
}
}
}
30 changes: 3 additions & 27 deletions src/Serilog.Extensions.Logging/Extensions/Logging/SerilogLogger.cs
Original file line number Diff line number Diff line change
Expand Up @@ -29,12 +29,9 @@ internal static string GetKeyWithoutFirstSymbol(ConcurrentDictionary<string, str
readonly SerilogLoggerProvider _provider;
readonly ILogger _logger;

static readonly CachingMessageTemplateParser MessageTemplateParser = new();
readonly EventIdPropertyCache _eventPropertyCache = new (48);

// It's rare to see large event ids, as they are category-specific
static readonly LogEventProperty[] LowEventIdValues = Enumerable.Range(0, 48)
.Select(n => new LogEventProperty("Id", new ScalarValue(n)))
.ToArray();
static readonly CachingMessageTemplateParser MessageTemplateParser = new();

public SerilogLogger(
SerilogLoggerProvider provider,
Expand Down Expand Up @@ -155,7 +152,7 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
}

if (eventId.Id != 0 || eventId.Name != null)
properties.Add(CreateEventIdProperty(eventId));
properties.Add(this._eventPropertyCache.GetOrCreateProperty(in eventId));

var (traceId, spanId) = Activity.Current is { } activity ?
(activity.TraceId, activity.SpanId) :
Expand All @@ -172,25 +169,4 @@ LogEvent PrepareWrite<TState>(LogEventLevel level, EventId eventId, TState state
stateObj = formatter(state, null);
return stateObj ?? state;
}

internal static LogEventProperty CreateEventIdProperty(EventId eventId)
{
var properties = new List<LogEventProperty>(2);

if (eventId.Id != 0)
{
if (eventId.Id >= 0 && eventId.Id < LowEventIdValues.Length)
// Avoid some allocations
properties.Add(LowEventIdValues[eventId.Id]);
else
properties.Add(new LogEventProperty("Id", new ScalarValue(eventId.Id)));
}

if (eventId.Name != null)
{
properties.Add(new LogEventProperty("Name", new ScalarValue(eventId.Name)));
}

return new LogEventProperty("EventId", new StructureValue(properties));
}
}
12 changes: 12 additions & 0 deletions test/Serilog.Extensions.Logging.Benchmarks/LogEventBenchmark.cs
Original file line number Diff line number Diff line change
Expand Up @@ -34,6 +34,7 @@ private class Person

readonly IMelLogger _melLogger;
readonly Person _bob, _alice;
readonly EventId _eventId = new EventId(1, "Test");

public LogEventBenchmark()
{
Expand Down Expand Up @@ -61,5 +62,16 @@ public void LogInformationScoped()
using (var scope = _melLogger.BeginScope("Hi {@User} from {$Me}", _bob, _alice))
_melLogger.LogInformation("Hi");
}

[Benchmark]
public void LogInformation_WithEventId()
{
this._melLogger.Log(
LogLevel.Information,
_eventId,
"Hi {@User} from {$Me}",
_bob,
_alice);
}
}
}
36 changes: 36 additions & 0 deletions test/Serilog.Extensions.Logging.Tests/EventIdPropertyCacheTests.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,36 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.

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

namespace Serilog.Extensions.Logging.Tests
{
public class EventIdPropertyCacheTests
{
[Theory]
[InlineData(1)]
[InlineData(10)]
[InlineData(48)]
[InlineData(100)]
public void LowAndHighNumberedEventIdsAreMapped(int id)
{
// Arrange
var cache = new EventIdPropertyCache(48);

var eventId = new EventId(id, "test");

// Act
var mapped = cache.GetOrCreateProperty(eventId);

// Assert
var value = Assert.IsType<StructureValue>(mapped.Value);
Assert.Equal(2, value.Properties.Count);

var idValue = value.Properties.Single(p => p.Name == "Id").Value;
var scalar = Assert.IsType<ScalarValue>(idValue);
Assert.Equal(id, scalar.Value);
}
}
}
16 changes: 0 additions & 16 deletions test/Serilog.Extensions.Logging.Tests/SerilogLoggerTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -517,22 +517,6 @@ public void Dispose()
}
}

[Theory]
[InlineData(1)]
[InlineData(10)]
[InlineData(48)]
[InlineData(100)]
public void LowAndHighNumberedEventIdsAreMapped(int id)
{
var orig = new EventId(id, "test");
var mapped = SerilogLogger.CreateEventIdProperty(orig);
var value = Assert.IsType<StructureValue>(mapped.Value);
Assert.Equal(2, value.Properties.Count);
var idValue = value.Properties.Single(p => p.Name == "Id").Value;
var scalar = Assert.IsType<ScalarValue>(idValue);
Assert.Equal(id, scalar.Value);
}

[Fact]
public void MismatchedMessageTemplateParameterCountIsHandled()
{
Expand Down