Don't force lazy message formatting for every message record

[YuliiaKovalova]

Summary

OnMessageRead forces lazy message formatting for every message record the reader materializes, which costs ~7% of total replay time on large binlogs and destroys the arguments array on the events handed to consumers.

Introduced by #961 (filtered binary log replay), so it is in 2.3.244 but not 2.3.240. It affects all consumers, including those that never set an EventFilter.

The problem

#961 extracted ProcessCultureMessage out of OnMessageRead and, in doing so, moved the sawCulture early-out into the callee:

// before (<= 2.3.240)
private void OnMessageRead(BuildMessageEventArgs args)
{
    if (sawCulture)
    {
        return;               // args.Message never touched
    }
    ...
}

// after (2.3.244)
private void OnMessageRead(BuildMessageEventArgs args)
    => ProcessCultureMessage(args.SenderName, args.Message);   // args.Message evaluated first

args.Message is now evaluated at the call site on every message record, before anything can short-circuit it. BuildMessageEventArgs inherits LazyFormattedBuildEventArgs.Message, which — when the event carries a non-empty arguments array — runs FormatString and then replaces the arguments array with the formatted string.

Two consequences:

1. Wasted work. The CurrentUICulture marker is emitted at the very start of the log, so after the first few records sawCulture is already true and the formatted string is discarded immediately.
2. Observable state change. Because the getter collapses argumentsOrFormattedMessage, Reflector.GetArguments(...) returns null for those events afterwards. BuildEventArgsWriter guards on Reflector.GetArguments(lazy) is { Length: > 0 }, so a read → write consumer now serializes a fully formatted message instead of template + arguments. (I verified GetArguments returns null for these events; I did not measure the resulting output-size impact.)

This fix restores the pre-#961 behavior exactly: arguments stay lazy until someone actually asks for .Message.

Measurements

Workload: one real 452 MB binlog, 21,914,589 records, replayed through a consumer that does not read every message string.

Instrumented run (BinLogReader.Replay, no EventFilter), reading the private field by reflection so the probe itself does not force formatting:

	2.3.244	with this fix
message events with arguments still intact	6,896,570	12,238,795
message events collapsed to a formatted string	5,342,225	0
total allocated	16,133,458,128 B	13,964,648,752 B
Gen0 / Gen1 collections	950 / 476	820 / 398

So the fix avoids ~5.34M eager string.Format calls and ~2.02 GiB of transient allocation on this log. Peak working set is unchanged — this is Gen0 churn, not retention.

End-to-end, indexing the same binlog. Identical application build, only StructuredLogger.dll swapped; 1 discarded warmup + 5 measured cycles in Latin-square order, cache cleared before every run; median of per-cycle paired ratios, range across the 5 cycles:

	wall	CPU
2.3.240 → 2.3.244	+7.60% (5.24 … 8.31)	+7.19% (5.75 … 8.97)
2.3.244 → 2.3.244 + fix	−6.56% (−7.44 … −4.62)	−6.88% (−7.65 … −4.70)
2.3.240 → 2.3.244 + fix	+0.12% (−1.39 … 1.52)	−0.24% (−1.87 … 2.40)

The last row is the point: after this change, 2.3.244 is statistically indistinguishable from 2.3.240, so no other part of #961 has a measurable cost. The machine was a shared VM with background load, hence the ranges; CPU time tracks wall time closely, which is itself evidence the cost is compute rather than contention.

I also bisected to confirm the range: 2.3.204 → 2.3.213 was +0.07% wall, 2.3.213 → 2.3.244 was +9.43%, and within that, 2.3.213 → 2.3.240 was −0.69% while 2.3.240 → 2.3.244 was +8.42%. v2.3.240...v2.3.244 contains only the #961 commits.

Scope of the benefit

This helps consumers that don't need every message string (indexers, filtered replay, binlogtool scenarios). The viewer's own MessageProcessor.AddMessage reads args.Message anyway, so for the viewer the formatting is deferred rather than eliminated and the gain is roughly nil. It should not be slower for anyone.

Correctness

• Index output for the consumer I measured is byte-identical across all 15 runs of 2.3.240 / 2.3.244 / 2.3.244+fix. That establishes equivalence for that workload; the arguments-collapse difference described above is by design the thing being restored, and is observable to consumers that re-serialize.
• The duplicated sawCulture check is deliberate: ProcessCultureMessage still needs its own, because the filtered path calls it directly with an already-materialized commonFields.Message string (that path is unaffected and left alone).
• Test suite: 98 passed / 3 failed / 1 skipped, and the same 3 fail identically on unmodified main, on v2.3.240 and on v2.3.213. They fail with MissingMethodException: FrozenSet.Create under net472 — a pre-existing environment/binding issue on my machine, unrelated to this change.

I didn't add a test, since asserting "this property was not read" isn't really expressible against the public surface. Happy to add one if you have a preferred approach.

[KirillOsenkov]

Published 2.3.246