Performance optimizations

[chris-peterson]

Context

EventContext is the object every logged event flows through: you construct one, set fields on it, time blocks with it, and disposing it renders one key=value line. Each event was costing 12,180 bytes — three ConcurrentDictionary instances, a Stopwatch, LINQ sorting in Render(), and three separate dictionary passes to normalize keys. In a service logging at volume that is most of the GC pressure.

Storage is now flat string[]/object[] arrays behind a private lock, scanned linearly. At the 10-20 fields a real event carries, a linear scan beats hashing — and because insertion order falls out of an array for free, the ordering tuple and the counter that fed it both disappear along with the sort.

	v6.4.7	this branch
throughput	187,708 ops/sec	563,696 ops/sec	3.0x
latency	5.33 µs/op	1.77 µs/op
bytes/op	12,180	4,183	−66%
GC gen1	481	437

Both numbers come from the same harness over 60s — Benchmarks.Baseline links the candidate's harness source and swaps only the Spiffy.Monitoring reference, so the two runs can't drift apart. Gen0 count is flat: allocation rate is similar, but each event costs a third as much, so the same collections cover three times the events.

The version bump is still owed — the csproj is at 6.4.7, which is already on nuget.org, so publish.yml would skip this on a release until it moves.

Review guide

Core change — read these first

• EventContext.cs — the arrays that replace the dictionaries, plus FindKey and AppendEntry. FindKey throws on a null key: suppressed fields tombstone their slot by nulling it, so an unguarded null would address whichever field was suppressed first.
• Render() holds the lock for its whole walk — it reads _keys/_vals/_count, which are only consistent between mutations, and its own TimeElapsed write is a mutation. The ConcurrentDictionary this replaces made that safe for free; arrays don't.
• AutoTimer.cs — timestamp arithmetic instead of a Stopwatch per event.

Behavior worth checking

• WriteTimerValues routes timer keys through NormalizeKey. Skipping it let ctx.Time(routeName) put whitespace straight into the delimited line and forge a field — Timer_keys_are_normalized pins it.
• StateMachineTypePattern and its sibling resolve component/operation for the parameterless ctor. Lambdas, local functions and generic async methods each nest differently; the tests cover all three.
• StackTraceCleanup.cs replaces Ben.Demystifier. It runs on every framework and short-circuits on traces with no <, so the ordinary case pays one IndexOf. Its tests are what caught its replacement strings dropping the separator between type and method.
• Quote selection in RequiresEncapsulation no longer depends on which quote appears first — a'b"c used to be wrapped in ', a character it contains.

Footnotes

• ThroughputHarness calls Initialize, not Create; only Initialize assigns Configuration.Default, which is what the contexts it builds bind.
• Dropped Ben.Demystifier and System.Diagnostics.StackTrace; TimerCollection.ShallowClone, GlobalEventContext.CopyTo and StringExtensions.ContainsWhiteSpace all lost their last callers.

Approach & trade-offs

FindKey is O(n). At <20 fields the cache-friendly scan wins on measurement; a service that puts hundreds of fields on one event would not. Worth flagging because nothing enforces the assumption.

The lock is a private object, not EventContext. Locking on this would let any caller holding a context contend with the library's own critical sections — including the user-supplied BeforeLoggingActions that run during Dispose().

StackTraceCleanup swallows RegexMatchTimeoutException and returns the trace uncleaned. The alternative is throwing out of IncludeException and breaking the caller's logging path. It matches how the surrounding code already treats logging failures, but it is a deliberate choice rather than an obvious one.

Output ordering changes. Count fields render after value fields rather than interleaved by insertion order, and timer fields sort ordinally rather than by current culture. Both are improvements; both are visible to anything parsing the output positionally.