Skip to content

MessageService: hot-path Debug logs summarize, never serialize the payload - #608

Merged
rbuergi merged 1 commit into
mainfrom
fix/hot-path-log-serialization
Jul 23, 2026
Merged

rbuergi merged 1 commit into
mainfrom
fix/hot-path-log-serialization

Conversation

@rbuergi

@rbuergi rbuergi commented Jul 23, 2026

Copy link
Copy Markdown
Contributor

The flake (CI shard 0, 2026-07-21: ExportImportAccessControlTest watchdog-killed at 60s; locally: CrossHubPatchAtomicityTest killed at 104–113s in 5 out of 5 bulk runs)

Debugged per the /debug skill — bulk repro, phase-trace timeline, then a mid-storm dotnet-stack + 10 GB dotnet-dump of the xUnit v3 test process:

  • The per-delivery Debug logs (Start processing …, Deserializing …) rendered the delivery via LogText — a full JSON serialization of the message payload. LoggingSerializerOptions only strips properties explicitly marked [PreventLogging]; everything else serializes whole.
  • CrossHubPatchAtomicityTest's 1,152-write cross-hub burst carries a node whose dict grows to 288 entries — the discarded log JSON grows quadratically. Measured inside the one test: +3.9 GiB managed, ~14k gen-0 GCs; the mid-storm heap dump shows 2.7 GB of live System.String (69% of the heap) and 40 action-block threads inside LogText's serializer.
  • The GC storm starves every action block in the process, so whichever test shares the process gets watchdog-killed — the 'different victim each run' shard flake.

Fix

Hot-path Debug lines now log a cheap LogSummary (type, id, sender → target, state). The full LogText payload render stays on the rare error path, where it's worth its cost.

Verification (same bulk run + Debug logging that reproduced 5/5)

before after
CrossHubPatchAtomicityTest 104–113s, watchdog-killed 16s, green
Full MeshWeaver.AI.Test suite ~5m45s, 1 failed 3m22s–3m27s, 889/889 green ×2
Memory-pressure watchdog events MEM_CRITICAL 6.5 GiB 0

Note: a rarer, distinct silent-stall flake at Warning level (the CI ExportImportAccessControlTest instance — flat memory, zero activity, matches the SubscribeRequest-race the MeshNodeStreamCache comments document) is not addressed here; this PR removes the dominant, proven storm.

🤖 Generated with Claude Code

https://claude.ai/code/session_01NGgWKSgL8pgrbg86xqfa6o

…yload

The per-delivery Debug logs (start-processing, deserializing) rendered the
delivery through LogText — a full JSON serialization of the message payload.
LoggingSerializerOptions only strips properties explicitly marked
[PreventLogging], so a burst of cross-hub patches carrying fat unmarked
payloads serialized the whole node into a log string on EVERY delivery.

Proven with CrossHubPatchAtomicityTest run in the full-suite bulk (the way CI
shard 0 runs it) with Debug logging enabled: +3.9 GiB managed / ~14k gen-0 GCs
inside the single test, 2.7 GB of live log strings in a mid-storm heap dump
(69% of the heap), 40 action-block threads inside LogText's serializer, and the
test watchdog-killed at 104-113s in 5/5 runs. Whatever test shares the process
gets starved too — the 'different victim each run' CI shard flake.

Hot-path Debug lines now log a cheap type/id/sender→target/state summary
(LogSummary); the full LogText payload render stays on the rare error path
where it is worth its cost. With the fix the same bulk run is green, the test
takes 16s (was 104-113s), the suite drops 5m45s → 3m22s, and zero memory-
pressure watchdog events fire.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01NGgWKSgL8pgrbg86xqfa6o
Copilot AI review requested due to automatic review settings July 23, 2026 09:05

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Pull request overview

Updates MessageService hot-path Debug logging to avoid expensive JSON payload serialization on every delivery, reducing allocations/GC pressure during high-throughput message bursts.

Changes:

  • Introduces a cheap LogSummary(IMessageDelivery) helper for per-delivery Debug logs.
  • Switches “Start processing …” and “Deserializing …” Debug logs from LogText(...) (JSON serialization) to LogSummary(...).
  • Keeps full LogText(...) payload rendering on the exception/error path.

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

Comment on lines +161 to +163
private static string LogSummary(IMessageDelivery delivery) =>
$"{delivery.Message?.GetType().Name ?? "(null)"} (ID: {delivery.Id}, "
+ $"{delivery.Sender} -> {delivery.Target}, {delivery.State})";
@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 3)

   12 files  ±0     12 suites  ±0   4m 14s ⏱️ -11s
  961 tests ±0    957 ✅ ±0  4 💤 ±0  0 ❌ ±0 
1 022 runs  ±0  1 018 ✅ ±0  4 💤 ±0  0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 0)

934 tests  ±0   928 ✅ ±0   4m 55s ⏱️ +9s
  5 suites ±0     6 💤 ±0 
  5 files   ±0     0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 5)

1 088 tests  ±0   1 087 ✅ ±0   5m 47s ⏱️ +28s
   12 suites ±0       1 💤 ±0 
   12 files   ±0       0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 4)

1 903 tests  ±0   1 715 ✅ ±0   5m 4s ⏱️ ±0s
   12 suites ±0     188 💤 ±0 
   12 files   ±0       0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 1)

1 146 tests  ±0   1 145 ✅ ±0   6m 40s ⏱️ +9s
   10 suites ±0       1 💤 ±0 
   10 files   ±0       0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results (shard 2)

1 105 tests  ±0   1 002 ✅ ±0   5m 26s ⏱️ +40s
   10 suites ±0     103 💤 ±0 
   10 files   ±0       0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@github-actions

Copy link
Copy Markdown
Contributor

Test Results

   61 files  ±0     61 suites  ±0   32m 8s ⏱️ + 1m 15s
7 137 tests ±0  6 834 ✅ ±0  303 💤 ±0  0 ❌ ±0 
7 198 runs  ±0  6 895 ✅ ±0  303 💤 ±0  0 ❌ ±0 

Results for commit 9e2b536. ± Comparison against base commit 9558ce8.

@rbuergi
rbuergi merged commit a472b19 into main Jul 23, 2026
16 checks passed
@rbuergi
rbuergi deleted the fix/hot-path-log-serialization branch July 23, 2026 09:29
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants