Skip to content

Commit 197262a

Browse files
Performance optimizations and benchmark harness
Add BenchmarkDotNet-based performance harness (tests/Benchmarks) covering EventContext lifecycle, StringExtensions, and render path scenarios with a throughput harness for end-to-end ops/sec measurement. Performance optimizations applied: - Replace Regex-based ContainsWhiteSpace with char.IsWhiteSpace loop - Replace LINQ Array.Contains in RequiresEncapsulation with bitmask lookup - Replace LINQ .Where().ToList() in key normalization with lazy List allocation - Replace LINQ OrderBy+Select+ToArray in GetKeyValuePairsAsDelimitedString with StringBuilder - Replace LINQ .Any() on arrays with .Length > 0 - Eliminate intermediate dictionary allocation in GetCountValues/GetTimeValues - Replace string.Format/interpolation with string.Concat in hot paths - Eliminate unnecessary .ToArray() in AddValues(IEnumerable) - Pre-size dictionary in Render() to reduce rehashing Replace Ben.Demystifier (unmaintained since 2021) with lightweight StackTraceCleanup using regex on netstandard2.0 and no-op on net8.0+ where the runtime already produces clean traces. Update target framework from net8.0 to net10.0 across all test projects, library multi-target, and CI workflows. Throughput: 424,174 ops/sec (4.4x faster than 6.4.7 baseline) Allocation: 5,630 bytes/op (59% less than 6.4.7 baseline)
1 parent 5a39e2b commit 197262a

22 files changed

Lines changed: 815 additions & 104 deletions

‎.github/workflows/api-compatibility.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -32,7 +32,7 @@ jobs:
3232
- name: Setup .NET
3333
uses: actions/setup-dotnet@v4
3434
with:
35-
dotnet-version: '8.0.x'
35+
dotnet-version: 10.0.x
3636

3737
- name: Install Microsoft.DotNet.ApiCompat.Tool
3838
run: dotnet tool install --global Microsoft.DotNet.ApiCompat.Tool

‎.github/workflows/ci.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,7 +19,7 @@ jobs:
1919
- name: Setup .NET
2020
uses: actions/setup-dotnet@v4
2121
with:
22-
dotnet-version: 8.0.x
22+
dotnet-version: 10.0.x
2323

2424
- name: Build
2525
run: dotnet build

‎.github/workflows/publish.yml‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ jobs:
2020
- name: Setup .NET
2121
uses: actions/setup-dotnet@v4
2222
with:
23-
dotnet-version: 8.0.x
23+
dotnet-version: 10.0.x
2424

2525
- name: Build
2626
run: dotnet build

‎.gitignore‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -110,3 +110,6 @@ UpgradeLog*.XML
110110
project.lock.json
111111
.vs/
112112
.vscode/
113+
114+
# BenchmarkDotNet
115+
BenchmarkDotNet.Artifacts/

‎Spiffy.Monitoring.sln‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,6 +27,8 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Spiffy.Monitoring.Aws", "sr
2727
EndProject
2828
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "TestWebApp", "tests\TestWebApp\TestWebApp.csproj", "{4DF62688-C556-4439-93C1-2E4562E07F42}"
2929
EndProject
30+
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "Benchmarks", "tests\Benchmarks\Benchmarks.csproj", "{B1A2C3D4-E5F6-7890-ABCD-EF1234567890}"
31+
EndProject
3032
Global
3133
GlobalSection(SolutionConfigurationPlatforms) = preSolution
3234
Debug|Any CPU = Debug|Any CPU
@@ -65,6 +67,10 @@ Global
6567
{4DF62688-C556-4439-93C1-2E4562E07F42}.Debug|Any CPU.Build.0 = Debug|Any CPU
6668
{4DF62688-C556-4439-93C1-2E4562E07F42}.Release|Any CPU.ActiveCfg = Release|Any CPU
6769
{4DF62688-C556-4439-93C1-2E4562E07F42}.Release|Any CPU.Build.0 = Release|Any CPU
70+
{B1A2C3D4-E5F6-7890-ABCD-EF1234567890}.Debug|Any CPU.ActiveCfg = Debug|Any CPU
71+
{B1A2C3D4-E5F6-7890-ABCD-EF1234567890}.Debug|Any CPU.Build.0 = Debug|Any CPU
72+
{B1A2C3D4-E5F6-7890-ABCD-EF1234567890}.Release|Any CPU.ActiveCfg = Release|Any CPU
73+
{B1A2C3D4-E5F6-7890-ABCD-EF1234567890}.Release|Any CPU.Build.0 = Release|Any CPU
6874
EndGlobalSection
6975
GlobalSection(SolutionProperties) = preSolution
7076
HideSolutionNode = FALSE
@@ -77,5 +83,6 @@ Global
7783
{9AD4DAE4-10DB-4933-9A28-6D0F994ADC17} = {8DEB13B2-A275-40CB-8D0F-AA672DB5717E}
7884
{E7E90469-1E8B-4204-9990-48CD0C42E481} = {8DEB13B2-A275-40CB-8D0F-AA672DB5717E}
7985
{4DF62688-C556-4439-93C1-2E4562E07F42} = {2DF31750-1635-4C57-980C-23EA82B2DE53}
86+
{B1A2C3D4-E5F6-7890-ABCD-EF1234567890} = {2DF31750-1635-4C57-980C-23EA82B2DE53}
8087
EndGlobalSection
8188
EndGlobal

‎src/Spiffy.Monitoring/EventContext.cs‎

Lines changed: 151 additions & 57 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,9 @@
22
using System.Collections.Concurrent;
33
using System.Collections.Generic;
44
using System.Diagnostics;
5-
using System.Linq;
5+
using System.Reflection;
6+
using System.Text;
7+
using System.Text.RegularExpressions;
68
using Spiffy.Monitoring.Config.Formatting;
79
using Spiffy.Monitoring.Config.Naming;
810

@@ -28,13 +30,43 @@ internal EventContext(string component, string operation, Configuration config)
2830

2931
public EventContext() : this(null, null)
3032
{
31-
var enhancedStackTrace = new EnhancedStackTrace(new StackTrace(skipFrames: 1));
33+
var stackTrace = new StackTrace(skipFrames: 1);
34+
var frames = stackTrace.GetFrames();
35+
if (frames != null)
36+
{
37+
foreach (var frame in frames)
38+
{
39+
var method = frame.GetMethod();
40+
if (method?.DeclaringType != null)
41+
{
42+
var caller = ResolveCaller(method);
43+
Initialize(caller.Component, caller.Operation);
44+
break;
45+
}
46+
}
47+
}
48+
}
49+
50+
// Compiler-generated types (async state machines, lambdas) have a declaring type
51+
// like "Namespace.OuterClass+<MethodName>d__5". We resolve back to the outer class
52+
// and original method name.
53+
static readonly Regex GeneratedTypePattern = new Regex(
54+
@"^<(\w+)>[a-z]__\d+$", RegexOptions.Compiled);
3255

33-
var caller = enhancedStackTrace
34-
.First(f => f.MethodInfo.DeclaringType != null)
35-
.MethodInfo;
56+
static (string Component, string Operation) ResolveCaller(MethodBase method)
57+
{
58+
var declaringType = method.DeclaringType;
59+
60+
if (declaringType.DeclaringType != null)
61+
{
62+
var match = GeneratedTypePattern.Match(declaringType.Name);
63+
if (match.Success)
64+
{
65+
return (declaringType.DeclaringType.Name, match.Groups[1].Value);
66+
}
67+
}
3668

37-
Initialize(caller.DeclaringType.Name, caller.Name);
69+
return (declaringType.Name, method.Name);
3870
}
3971

4072
public EventContext(string component, string operation) : this(component, operation, null)
@@ -134,7 +166,10 @@ public void AddValues(params KeyValuePair<string, object>[] values)
134166

135167
public void AddValues(IEnumerable<KeyValuePair<string, object>> values)
136168
{
137-
AddValues(values.ToArray());
169+
foreach (var kvp in values)
170+
{
171+
this[kvp.Key] = kvp.Value;
172+
}
138173
}
139174

140175
public bool Contains(string key)
@@ -207,7 +242,7 @@ public void Dispose()
207242
if (!IsSuppressed)
208243
{
209244
var logActions = _config.LoggingActions;
210-
if (logActions.Any())
245+
if (logActions.Length > 0)
211246
{
212247
var logEvent = Render();
213248
foreach (var logAction in logActions)
@@ -235,29 +270,31 @@ public void Initialize(string component, string operation)
235270

236271
private LogEvent Render()
237272
{
238-
IEnumerable<KeyValuePair<string, (uint Order, object Value)>> values = _values;
239-
if (_config.CustomNullValue == null)
273+
// Sort values by insertion order, filter nulls if no custom null value
274+
var sorted = new List<KeyValuePair<string, (uint Order, object Value)>>(_values.Count);
275+
foreach (var kvp in _values)
240276
{
241-
values = values.Where(kvp => kvp.Value.Value != null);
277+
if (_config.CustomNullValue != null || kvp.Value.Value != null)
278+
{
279+
sorted.Add(kvp);
280+
}
242281
}
243-
var kvps = values
244-
.OrderBy(x => x.Value.Order)
245-
.ToDictionary(
246-
kvp => kvp.Key,
247-
kvp => GetValue(kvp.Value.Value));
282+
sorted.Sort((a, b) => a.Value.Order.CompareTo(b.Value.Order));
248283

249-
foreach (var kvp in GetCountValues())
284+
var kvps = new Dictionary<string, string>(sorted.Count + _counts.Count + 8);
285+
foreach (var kvp in sorted)
250286
{
251-
kvps.Add(kvp.Key, kvp.Value);
287+
kvps[kvp.Key] = GetValue(kvp.Value.Value);
252288
}
253289

254-
foreach (var kvp in GetTimeValues())
290+
foreach (var kvp in _counts)
255291
{
256-
kvps.Add(kvp.Key, kvp.Value);
292+
kvps[kvp.Key] = kvp.Value.Value.ToString();
257293
}
258294

259-
GenerateKeysIfNecessary(kvps);
295+
GetTimeValues(kvps);
260296

297+
GenerateKeysIfNecessary(kvps);
261298
ReplaceKeysThatHaveWhiteSpace(kvps);
262299
ReplaceKeysThatHaveDots(kvps);
263300
EncapsulateValuesIfNecessary(kvps);
@@ -266,7 +303,7 @@ private LogEvent Render()
266303
var formattedTimeElapsed = GetTimeFor(timeElapsedMs);
267304
this[FieldName.Get(Field.TimeElapsed)] = formattedTimeElapsed;
268305
kvps[FieldName.Get(Field.TimeElapsed)] = formattedTimeElapsed;
269-
PrivateData["MetricsKey"] = $"{Component}/{Operation}";
306+
PrivateData["MetricsKey"] = string.Concat(Component, "/", Operation);
270307

271308
return new LogEvent(
272309
Level,
@@ -299,43 +336,104 @@ void EncapsulateValuesIfNecessary(IDictionary<string, string> keyValuePairs)
299336

300337
private static void ReplaceKeysThatHaveWhiteSpace(Dictionary<string, string> keyValuePairs)
301338
{
302-
foreach (var kvp in keyValuePairs
303-
.Where(k => k.Key.ContainsWhiteSpace())
304-
.ToList())
339+
List<KeyValuePair<string, string>> toReplace = null;
340+
foreach (var kvp in keyValuePairs)
341+
{
342+
if (kvp.Key.ContainsWhiteSpace())
343+
{
344+
(toReplace ??= new List<KeyValuePair<string, string>>()).Add(kvp);
345+
}
346+
}
347+
if (toReplace != null)
305348
{
306-
keyValuePairs.Remove(kvp.Key);
307-
keyValuePairs[kvp.Key.RemoveWhiteSpace()] = kvp.Value;
349+
foreach (var kvp in toReplace)
350+
{
351+
keyValuePairs.Remove(kvp.Key);
352+
keyValuePairs[kvp.Key.RemoveWhiteSpace()] = kvp.Value;
353+
}
308354
}
309355
}
310356

311357
private static void ReplaceKeysThatHaveDots(Dictionary<string, string> keyValuePairs)
312358
{
313-
foreach (var kvp in keyValuePairs
314-
.Where(k => k.Key.Contains("."))
315-
.ToList())
359+
List<KeyValuePair<string, string>> toReplace = null;
360+
foreach (var kvp in keyValuePairs)
361+
{
362+
if (kvp.Key.Contains("."))
363+
{
364+
(toReplace ??= new List<KeyValuePair<string, string>>()).Add(kvp);
365+
}
366+
}
367+
if (toReplace != null)
316368
{
317-
keyValuePairs.Remove(kvp.Key);
318-
keyValuePairs[kvp.Key.Replace(".", "_")] = kvp.Value;
369+
foreach (var kvp in toReplace)
370+
{
371+
keyValuePairs.Remove(kvp.Key);
372+
keyValuePairs[kvp.Key.Replace(".", "_")] = kvp.Value;
373+
}
319374
}
320375
}
321376

322377
private void GenerateKeysIfNecessary(Dictionary<string, string> keyValuePairs)
323378
{
324-
foreach (var kvp in keyValuePairs
325-
.Where(k => string.IsNullOrWhiteSpace(k.Key))
326-
.ToList())
379+
List<KeyValuePair<string, string>> toReplace = null;
380+
foreach (var kvp in keyValuePairs)
381+
{
382+
if (string.IsNullOrWhiteSpace(kvp.Key))
383+
{
384+
(toReplace ??= new List<KeyValuePair<string, string>>()).Add(kvp);
385+
}
386+
}
387+
if (toReplace != null)
327388
{
328-
keyValuePairs.Remove(kvp.Key);
329-
keyValuePairs[$"GeneratedKey({Guid.NewGuid()})"] = kvp.Value;
389+
foreach (var kvp in toReplace)
390+
{
391+
keyValuePairs.Remove(kvp.Key);
392+
keyValuePairs[string.Concat("GeneratedKey(", Guid.NewGuid().ToString(), ")")] = kvp.Value;
393+
}
330394
}
331395
}
332396

333397
private string GetKeyValuePairsAsDelimitedString(Dictionary<string, string> keyValuePairs)
334398
{
335-
return string.Join(" ", keyValuePairs
336-
.OrderBy(pair => pair.Value.Length <= _config.DeprioritizedValueLength ? 0 : 1)
337-
.Select(kvp =>
338-
$"{kvp.Key}={kvp.Value}").ToArray());
399+
var deprioritizedLength = _config.DeprioritizedValueLength;
400+
401+
// Partition into short (priority) and long (deprioritized) without LINQ
402+
List<KeyValuePair<string, string>> shortValues = null;
403+
List<KeyValuePair<string, string>> longValues = null;
404+
bool hasLong = false;
405+
406+
foreach (var kvp in keyValuePairs)
407+
{
408+
if (kvp.Value.Length <= deprioritizedLength)
409+
{
410+
(shortValues ??= new List<KeyValuePair<string, string>>()).Add(kvp);
411+
}
412+
else
413+
{
414+
(longValues ??= new List<KeyValuePair<string, string>>()).Add(kvp);
415+
hasLong = true;
416+
}
417+
}
418+
419+
var sb = new StringBuilder();
420+
if (shortValues != null)
421+
{
422+
foreach (var kvp in shortValues)
423+
{
424+
if (sb.Length > 0) sb.Append(' ');
425+
sb.Append(kvp.Key).Append('=').Append(kvp.Value);
426+
}
427+
}
428+
if (hasLong)
429+
{
430+
foreach (var kvp in longValues)
431+
{
432+
if (sb.Length > 0) sb.Append(' ');
433+
sb.Append(kvp.Key).Append('=').Append(kvp.Value);
434+
}
435+
}
436+
return sb.ToString();
339437
}
340438

341439
string GetValue(object value)
@@ -378,29 +476,25 @@ private string RenderTimestamp()
378476
return ts;
379477
}
380478

381-
private IDictionary<string, string> GetCountValues()
479+
private void GetTimeValues(Dictionary<string, string> target)
382480
{
383-
return _counts.ToDictionary(
384-
k => k.Key,
385-
v => v.Value.Value.ToString());
386-
}
481+
var clone = Timers.ShallowClone();
482+
if (clone.Count == 0) return;
387483

388-
private IEnumerable<KeyValuePair<string, string>> GetTimeValues()
389-
{
390-
var times = new Dictionary<string, string>();
484+
var timeElapsedField = FieldName.Get(Field.TimeElapsed);
485+
// Sort keys for deterministic output
486+
var keys = new List<string>(clone.Keys);
487+
keys.Sort(StringComparer.Ordinal);
391488

392-
foreach (var kvp in Timers
393-
.ShallowClone()
394-
.OrderBy(x => x.Key))
489+
foreach (var key in keys)
395490
{
396-
times[$"{FieldName.Get(Field.TimeElapsed)}_{kvp.Key}"] = GetTimeFor(kvp.Value.ElapsedMilliseconds);
397-
if (kvp.Value.Count > 1)
491+
var timer = clone[key];
492+
target[string.Concat(timeElapsedField, "_", key)] = GetTimeFor(timer.ElapsedMilliseconds);
493+
if (timer.Count > 1)
398494
{
399-
times[$"Count_{kvp.Key}"] = kvp.Value.Count.ToString();
495+
target[string.Concat("Count_", key)] = timer.Count.ToString();
400496
}
401497
}
402-
403-
return times;
404498
}
405499

406500
private static string GetTimeFor(double milliseconds)

0 commit comments

Comments
 (0)