Skip to content

Commit f6a2dec

Browse files
evgenyfedorov2evgenyfedorov2
evgenyfedorov2
authored and
evgenyfedorov2
committed
Add more list pools
1 parent 5e49d69 commit f6a2dec

File tree

4 files changed

+151
-123
lines changed

4 files changed

+151
-123
lines changed

‎src/Libraries/Microsoft.AspNetCore.Diagnostics.Middleware/Buffering/IncomingRequestLogBuffer.cs

Lines changed: 15 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -16,7 +16,7 @@
1616

1717
namespace Microsoft.AspNetCore.Diagnostics.Buffering;
1818

19-
internal sealed class IncomingRequestLogBuffer
19+
internal sealed class IncomingRequestLogBuffer : IDisposable
2020
{
2121
private const int MaxBatchSize = 256;
2222
private static readonly ObjectPool<List<DeserializedLogRecord>> _recordsToEmitListPool =
@@ -28,7 +28,7 @@ internal sealed class IncomingRequestLogBuffer
2828
private readonly TimeProvider _timeProvider = TimeProvider.System;
2929
private readonly LogBufferingFilterRule[] _filterRules;
3030
private readonly Lock _bufferSwapLock = new();
31-
31+
private volatile bool _disposed;
3232
private ConcurrentQueue<SerializedLogRecord> _activeBuffer = new();
3333
private ConcurrentQueue<SerializedLogRecord> _standbyBuffer = new();
3434
private int _activeBufferSize;
@@ -109,7 +109,7 @@ public void Flush()
109109
_activeBuffer = _standbyBuffer;
110110
tempBuffer.Clear();
111111
_standbyBuffer = tempBuffer;
112-
Interlocked.Exchange(ref _activeBufferSize, 0);
112+
_ = Interlocked.Exchange(ref _activeBufferSize, 0);
113113
}
114114

115115
// Process records in batches
@@ -147,6 +147,18 @@ public void Flush()
147147
SerializedLogRecordFactory.Return(bufferedRecords);
148148
}
149149

150+
public void Dispose()
151+
{
152+
if (_disposed)
153+
{
154+
return;
155+
}
156+
157+
_disposed = true;
158+
159+
_ruleSelector.InvalidateCache();
160+
}
161+
150162
private void TrimExcessRecords()
151163
{
152164
while (_activeBufferSize > _options.CurrentValue.MaxPerRequestBufferSizeInBytes &&

‎src/Libraries/Microsoft.Extensions.Telemetry/Buffering/GlobalBuffer.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -128,7 +128,7 @@ public void Flush()
128128
_activeBuffer = _standbyBuffer;
129129
tempBuffer.Clear();
130130
_standbyBuffer = tempBuffer;
131-
Interlocked.Exchange(ref _activeBufferSize, 0);
131+
_ = Interlocked.Exchange(ref _activeBufferSize, 0);
132132
}
133133

134134
// Process records in batches

‎src/Libraries/Microsoft.Extensions.Telemetry/Buffering/LogBufferingFilterRuleSelector.cs

Lines changed: 27 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,8 @@
1111
using System.Collections.Generic;
1212
using System.Linq;
1313
using Microsoft.Extensions.Logging;
14+
using Microsoft.Extensions.ObjectPool;
15+
using Microsoft.Shared.Pools;
1416

1517
namespace Microsoft.Extensions.Diagnostics.Buffering;
1618

@@ -20,27 +22,42 @@ namespace Microsoft.Extensions.Diagnostics.Buffering;
2022
internal sealed class LogBufferingFilterRuleSelector
2123
{
2224
private static readonly IEqualityComparer<KeyValuePair<string, object?>> _stringifyComparer = new StringifyComprarer();
25+
private static readonly ObjectPool<List<LogBufferingFilterRule>> _rulePool =
26+
PoolFactory.CreateListPool<LogBufferingFilterRule>();
27+
28+
private readonly ObjectPool<List<LogBufferingFilterRule>> _cachedRulePool =
29+
PoolFactory.CreateListPool<LogBufferingFilterRule>();
2330
private readonly ConcurrentDictionary<(LogLevel, EventId), List<LogBufferingFilterRule>> _ruleCache = new();
2431

2532
public static LogBufferingFilterRule[] SelectByCategory(IList<LogBufferingFilterRule> rules, string category)
2633
{
27-
List<LogBufferingFilterRule> result = [];
28-
29-
// Skip rules with inapplicable category
30-
// because GlobalBuffers are created for each category
31-
foreach (LogBufferingFilterRule rule in rules)
34+
List<LogBufferingFilterRule> rulesOfCategory = _rulePool.Get();
35+
try
3236
{
33-
if (IsMatch(rule, category))
37+
// Select rules with applicable category only
38+
foreach (LogBufferingFilterRule rule in rules)
3439
{
35-
result.Add(rule);
40+
if (IsMatch(rule, category))
41+
{
42+
rulesOfCategory.Add(rule);
43+
}
3644
}
37-
}
3845

39-
return result.ToArray();
46+
return rulesOfCategory.ToArray();
47+
}
48+
finally
49+
{
50+
_rulePool.Return(rulesOfCategory);
51+
}
4052
}
4153

4254
public void InvalidateCache()
4355
{
56+
foreach (((LogLevel, EventId) key, List<LogBufferingFilterRule> value) in _ruleCache)
57+
{
58+
_cachedRulePool.Return(value);
59+
}
60+
4461
_ruleCache.Clear();
4562
}
4663

@@ -53,7 +70,7 @@ public void InvalidateCache()
5370
// 1. select rule candidates by log level and event id from the cache
5471
List<LogBufferingFilterRule> ruleCandidates = _ruleCache.GetOrAdd((logLevel, eventId), _ =>
5572
{
56-
List<LogBufferingFilterRule> candidates = new(rules.Count);
73+
List<LogBufferingFilterRule> candidates = _cachedRulePool.Get();
5774
foreach (LogBufferingFilterRule rule in rules)
5875
{
5976
if (IsMatch(rule, logLevel, eventId))

‎test/Libraries/Microsoft.Extensions.Telemetry.Tests/Logging/ExtendedLoggerTests.cs

Lines changed: 108 additions & 109 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@
44
using System;
55
using System.Collections.Generic;
66
using System.Linq;
7-
using System.Threading.Tasks;
87
using Microsoft.Extensions.Compliance.Testing;
98
using Microsoft.Extensions.DependencyInjection;
109
using Microsoft.Extensions.Diagnostics.Enrichment;
@@ -14,12 +13,13 @@
1413
using Moq;
1514
using Xunit;
1615
#if NET9_0_OR_GREATER
16+
using System.Threading.Tasks;
1717
using Microsoft.Extensions.Diagnostics.Buffering;
1818
#endif
1919

2020
namespace Microsoft.Extensions.Logging.Test;
2121

22-
public class ExtendedLoggerTests
22+
public static class ExtendedLoggerTests
2323
{
2424
[Theory]
2525
[CombinatorialData]
@@ -156,113 +156,6 @@ public static void Sampling()
156156
Assert.Equal(0, provider.Logger!.Collector.Count);
157157
}
158158

159-
#if NET9_0_OR_GREATER
160-
[Fact]
161-
public static void GlobalBuffering_CanonicalUsecase()
162-
{
163-
using var provider = new Provider();
164-
using ILoggerFactory factory = Utils.CreateLoggerFactory(
165-
builder =>
166-
{
167-
builder.AddProvider(provider);
168-
builder.AddGlobalBuffer(LogLevel.Warning);
169-
});
170-
171-
ILogger logger = factory.CreateLogger("my category");
172-
logger.LogWarning("MSG0");
173-
logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2");
174-
175-
// nothing is logged because the buffer not flushed yet
176-
Assert.Equal(0, provider.Logger!.Collector.Count);
177-
178-
// instead of this, users would get LogBuffer from DI and call Flush on it
179-
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
180-
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
181-
182-
buffer.Flush();
183-
184-
// 2 log records emitted because the buffer has been flushed
185-
Assert.Equal(2, provider.Logger!.Collector.Count);
186-
}
187-
188-
[Fact]
189-
public static void GlobalBuffering_ParallelLogging()
190-
{
191-
using var provider = new Provider();
192-
using ILoggerFactory factory = Utils.CreateLoggerFactory(
193-
builder =>
194-
{
195-
builder.AddProvider(provider);
196-
builder.AddGlobalBuffer(LogLevel.Warning);
197-
});
198-
199-
ILogger logger = factory.CreateLogger("my category");
200-
201-
// 1000 threads logging at the same time
202-
Parallel.For(0, 1000, _ =>
203-
{
204-
logger.LogWarning("MSG0");
205-
logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2");
206-
});
207-
208-
// nothing is logged because the buffer not flushed yet
209-
Assert.Equal(0, provider.Logger!.Collector.Count);
210-
211-
212-
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
213-
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
214-
215-
buffer.Flush();
216-
217-
// 2000 log records emitted because the buffer has been flushed
218-
Assert.Equal(2000, provider.Logger!.Collector.Count);
219-
}
220-
221-
[Fact]
222-
public async Task GlobalBuffering_ParallelLoggingAndFlushing()
223-
{
224-
// Arrange
225-
using var provider = new Provider();
226-
using ILoggerFactory factory = Utils.CreateLoggerFactory(
227-
builder =>
228-
{
229-
builder.AddProvider(provider);
230-
builder.AddGlobalBuffer(options =>
231-
{
232-
options.AutoFlushDuration = TimeSpan.Zero;
233-
options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Warning));
234-
});
235-
});
236-
237-
ILogger logger = factory.CreateLogger("my category");
238-
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
239-
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
240-
241-
// Act - Run logging and flushing operations in parallel
242-
await Task.Run(() =>
243-
{
244-
Parallel.For(0, 100, i =>
245-
{
246-
logger.LogWarning("MSG0");
247-
logger.LogWarning("MSG1");
248-
logger.LogWarning("MSG2");
249-
logger.LogWarning("MSG3");
250-
logger.LogWarning("MSG4");
251-
logger.LogWarning("MSG5");
252-
logger.LogWarning("MSG6");
253-
logger.LogWarning("MSG7");
254-
logger.LogWarning("MSG8");
255-
logger.LogWarning("MSG9");
256-
buffer.Flush();
257-
});
258-
});
259-
260-
buffer.Flush();
261-
Assert.Equal(1000, provider.Logger!.Collector.Count);
262-
}
263-
264-
#endif
265-
266159
[Theory]
267160
[CombinatorialData]
268161
public static void BagAndJoiner(bool objectVersion)
@@ -1026,6 +919,112 @@ public static void LegacyLogging_OriginalFormatMustBeLastInTheListOfStatePropert
1026919
Assert.Equal("V4", property.Value);
1027920
}
1028921

922+
#if NET9_0_OR_GREATER
923+
[Fact]
924+
public static void GlobalBuffering_CanonicalUsecase()
925+
{
926+
using var provider = new Provider();
927+
using ILoggerFactory factory = Utils.CreateLoggerFactory(
928+
builder =>
929+
{
930+
builder.AddProvider(provider);
931+
builder.AddGlobalBuffer(LogLevel.Warning);
932+
});
933+
934+
ILogger logger = factory.CreateLogger("my category");
935+
logger.LogWarning("MSG0");
936+
logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2");
937+
938+
// nothing is logged because the buffer not flushed yet
939+
Assert.Equal(0, provider.Logger!.Collector.Count);
940+
941+
// instead of this, users would get LogBuffer from DI and call Flush on it
942+
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
943+
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
944+
945+
buffer.Flush();
946+
947+
// 2 log records emitted because the buffer has been flushed
948+
Assert.Equal(2, provider.Logger!.Collector.Count);
949+
}
950+
951+
[Fact]
952+
public static void GlobalBuffering_ParallelLogging()
953+
{
954+
using var provider = new Provider();
955+
using ILoggerFactory factory = Utils.CreateLoggerFactory(
956+
builder =>
957+
{
958+
builder.AddProvider(provider);
959+
builder.AddGlobalBuffer(LogLevel.Warning);
960+
});
961+
962+
ILogger logger = factory.CreateLogger("my category");
963+
964+
// 1000 threads logging at the same time
965+
Parallel.For(0, 1000, _ =>
966+
{
967+
logger.LogWarning("MSG0");
968+
logger.Log(LogLevel.Warning, new EventId(2, "ID2"), "some state", null, (_, _) => "MSG2");
969+
});
970+
971+
// nothing is logged because the buffer not flushed yet
972+
Assert.Equal(0, provider.Logger!.Collector.Count);
973+
974+
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
975+
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
976+
977+
buffer.Flush();
978+
979+
// 2000 log records emitted because the buffer has been flushed
980+
Assert.Equal(2000, provider.Logger!.Collector.Count);
981+
}
982+
983+
[Fact]
984+
public static async Task GlobalBuffering_ParallelLoggingAndFlushing()
985+
{
986+
// Arrange
987+
using var provider = new Provider();
988+
using ILoggerFactory factory = Utils.CreateLoggerFactory(
989+
builder =>
990+
{
991+
builder.AddProvider(provider);
992+
builder.AddGlobalBuffer(options =>
993+
{
994+
options.AutoFlushDuration = TimeSpan.Zero;
995+
options.Rules.Add(new LogBufferingFilterRule(logLevel: LogLevel.Warning));
996+
});
997+
});
998+
999+
ILogger logger = factory.CreateLogger("my category");
1000+
Utils.DisposingLoggerFactory dlf = (Utils.DisposingLoggerFactory)factory;
1001+
GlobalLogBuffer buffer = dlf.ServiceProvider.GetRequiredService<GlobalLogBuffer>();
1002+
1003+
// Act - Run logging and flushing operations in parallel
1004+
await Task.Run(() =>
1005+
{
1006+
Parallel.For(0, 100, i =>
1007+
{
1008+
logger.LogWarning("MSG0");
1009+
logger.LogWarning("MSG1");
1010+
logger.LogWarning("MSG2");
1011+
logger.LogWarning("MSG3");
1012+
logger.LogWarning("MSG4");
1013+
logger.LogWarning("MSG5");
1014+
logger.LogWarning("MSG6");
1015+
logger.LogWarning("MSG7");
1016+
logger.LogWarning("MSG8");
1017+
logger.LogWarning("MSG9");
1018+
buffer.Flush();
1019+
});
1020+
});
1021+
1022+
buffer.Flush();
1023+
Assert.Equal(1000, provider.Logger!.Collector.Count);
1024+
}
1025+
1026+
#endif
1027+
10291028
private sealed class CustomLoggerProvider : ILoggerProvider
10301029
{
10311030
private readonly string _providerName;

0 commit comments

Comments
 (0)