Repository navigation
Conversation
Reduce redundant wakeups in the existing logging pipeline without changing event content or ordering. (cherry picked from commit 02aa3e5) Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: b1e43530-4bc8-42bb-b615-5c01fcdba4b9
There was a problem hiding this comment.
🟡 Changes recommended
Deterministic coverage is missing for the coalescing policy and concurrent shutdown behavior.
2 open findings
What changed in this PR
Coalesces asynchronous logging notifications to reduce producer overhead while preserving FIFO delivery and complete draining.
Changes:
- Batches notifications by count or delay, with urgent-event bypasses.
- Improves recursive drain and shutdown handling.
- Adds concurrency tests and updates documentation.
| File | Description |
|---|---|
LoggingService.cs |
Implements notification coalescing and drain handling. |
LoggingService_Tests.cs |
Adds callback-drain and producer-order tests. |
Logging-Internals.md |
Documents asynchronous coalescing semantics. |
🧠 Review effort: Balanced
| if (_logMode == LoggerMode.Asynchronous) | ||
| { | ||
| WaitForLoggingToProcessEvents(); |
| if (eventCount >= LoggingEventNotificationBatchSize || | ||
| ShouldProcessLoggingEventImmediately(loggingEvent)) | ||
| { | ||
| RequestImmediateLoggingEventProcessing(enqueueEvent); |
|
PR #15144 is an open draft covering the same asynchronous Warning Firewall blocked 4 domainsThe following domains were blocked by the firewall during workflow execution:
[!TIP] tools:
github:
mode: gh-proxySee GitHub Tools for more information on To allow these domains, add them to the network:
allowed:
- defaults
- "api.github.com"
- "cafe.github.com"
- "github.com"
- "raw.githubusercontent.com"See Network Configuration for more information.
|
|
Expert review verdict: changes requested.
✅ 20/24 dimensions clean. The blocking issue is that a stale Warning Firewall blocked 4 domainsThe following domains were blocked by the firewall during workflow execution:
[!TIP] tools:
github:
mode: gh-proxySee GitHub Tools for more information on To allow these domains, add them to the network:
allowed:
- defaults
- "api.github.com"
- "cafe.github.com"
- "github.com"
- "raw.githubusercontent.com"See Network Configuration for more information.
|
![github-actions[bot]](https://avatars.githubusercontent.com/in/15368?s=60&v=4){kind=small}
There was a problem hiding this comment.
Documentation Accuracy — ISSUE
SEVERITY: MODERATE
FILE: documentation/wiki/Logging-Internals.md
LINES: 136
SCENARIO: With asynchronous logging idle, enqueue a TaskStartedEventArgs. This is a lifecycle/status event, but ShouldProcessLoggingEventImmediately does not match it; the consumer enters the scheduled coalescing path and may wait 16 ms before delivery.
FINDING: “build lifecycle events ... request immediate processing” overstates the implementation. Only BuildStartedEventArgs, BuildFinishedEventArgs, and BuildCanceledEventArgs bypass coalescing; project, target, task, evaluation, and submission lifecycle events do not.
RECOMMENDATION: Replace “build lifecycle events” with the exact set: build-start, build-finish, and build-cancellation events.
Warning
Firewall blocked 4 domains
The following domains were blocked by the firewall during workflow execution:
api.github.comcafe.github.comgithub.comraw.githubusercontent.com
[!TIP]
api.github.com is blocked because GitHub API access uses the built-in GitHub tools by default. Instead of adding api.github.com to network.allowed, use tools.github.mode: gh-proxy for direct pre-authenticated GitHub CLI access without requiring network access to api.github.com:
tools:
github:
mode: gh-proxySee GitHub Tools for more information on gh-proxy mode.
To allow these domains, add them to the network.allowed list in your workflow frontmatter:
network:
allowed:
- defaults
- "api.github.com"
- "cafe.github.com"
- "github.com"
- "raw.githubusercontent.com"See Network Configuration for more information.
Generated by Expert Code Review (on open) for #15232 · copilot · gpt56 · 1K AIC · ⌖ 0.521 AIC · ⊞ 24.9K
|
|
||
| // Callbacks can enqueue more events, so wait for the entire queue and its last callback to finish. | ||
| while (loggingEventProcessingThread.IsAlive && | ||
| (!emptyQueueEvent.WaitOne(millisecondsTimeout: 50) || !eventQueue.IsEmpty)) |
There was a problem hiding this comment.
[BLOCKING] Concurrency & Thread Safety
WaitForLoggingToProcessEvents can return while the last logger callback is still executing because _emptyQueueEvent may still be set from the preceding idle generation.
Thread timeline:
T=0 Consumer: the previous drain leaves _emptyQueueEvent set
T=1 Producer: enqueues one event and wakes the consumer
T=2 Waiter: WaitOne(50) observes that stale set state
T=3 Consumer: resets the event, dequeues the sole event, and enters a blocking callback
T=4 Waiter: observes eventQueue.IsEmpty == true and exits ← the callback is still running
The signal and queue observation therefore need not describe the same drain generation.
Recommendation: Track accepted events through callback completion and signal only when that in-flight count reaches zero, or use a generation handshake that revalidates completion after observing an empty queue.
|
|
||
| Regardless of the mode used - sequential and isolated delivery of events is always guaranteed (single logger will not receive next event before returning from the previous, any logger will not receive an event while it's being processed by a different logger). The future versions might decide to deliver messages to separate loggers in independent mode - where a processing event by a single logger won't block other loggers. | ||
|
|
||
| In asynchronous mode, ordinary events enter the FIFO queue immediately, but consumer notifications are coalesced (currently at 64 events or a 16 ms coalescing wait). Errors, warnings, build lifecycle events, critical messages, and custom events request immediate processing. |
There was a problem hiding this comment.
[MODERATE] Documentation Accuracy
“Build lifecycle events” is broader than the implementation. TaskStartedEventArgs, ProjectStartedEventArgs, TargetStartedEventArgs, and evaluation lifecycle events do not match the immediate predicate and can still incur the coalescing delay.
Recommendation: Say “build-started, build-finished, and build-canceled events,” or expand the predicate if all lifecycle events are intended to bypass coalescing.
Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> Copilot-Session: b1e43530-4bc8-42bb-b615-5c01fcdba4b9
Related issue(s): None.
Context
Asynchronous logging currently signals the consumer for every queued event. On workloads with many short tasks, these redundant notifications make task-start/task-finish logging disproportionately expensive. Coalescing notifications reduces that producer-side overhead without batching or changing the events themselves.
Changes Made
Compatibility
Logging-mode defaults, event contents, serialization, and FIFO callback delivery remain unchanged. Synchronous logging is untouched. Asynchronous events can incur an additional coalescing wait; the 16 ms limit bounds that wait, not total logger delivery latency. Explicit drains and shutdown bypass it.
The batch size and delay are private constants, not new environment-variable configuration. No new public APIs, diagnostics, or dependencies are introduced.
Testing
Latest simplification, validated on Linux x64:
./build.sh -v quiet -p:CreateBootstrap=false-- passed, 0 warnings and 0 errors. Bootstrap regeneration was disabled to avoid replacing files used by the ongoing Release test run.artifacts/bin/Microsoft.Build.Engine.UnitTests/Debug/net11.0/Microsoft.Build.Engine.UnitTests --filter-class '*Logging*' --no-progress-- passed: 179 passed, 0 failed, 2 expected platform-specific skips.dotnet format whitespace src/Build/Microsoft.Build.csproj --include src/Build/BackEnd/Components/Logging/LoggingService.cs --no-restore --verify-no-changes-- passed; reported a workspace-loading warning, but no formatting changes.git diff --check-- passed.The Debug test host's
Microsoft.Build.dllwas verified byte-for-byte identical to the freshly built Debug engine. Existing regression tests are unchanged.Earlier validation, before this simplification:
./build.sh -v quiet-- passed, 0 warnings and 0 errors../artifacts/bin/bootstrap/core/dotnet --version-- passed,11.0.100-rc.1.26420.103../artifacts/bin/bootstrap/core/dotnet build src/Samples/Dependency/Dependency.csproj -v:q -nodeReuse:false-- passed, 0 warnings and 0 errors../artifacts/bin/bootstrap/core/dotnet msbuild -help-- passed../build.sh --test -c Release -v quiet-- still running on the earlier PR revision143361f29. Nine completed test projects, including the full core-engine test project, reported 8,556 passed, 0 failed, and 206 skipped/not-executed tests.Microsoft.Build.Engine.OM.UnitTestsandMicrosoft.Build.Tasks.UnitTestsremain in filesystem-enumeration tests; this is not an overall full-suite pass or full-suite validation of the latest simplification.The two callback-drain regression cases were also run against the earlier marker-based implementation and failed before the complete-drain fix. Windows and .NET Framework validation have not been run locally.
Performance measurements
These measurements compare baseline
74878b50awith the initial coalescing implementation (93636387e, a local pre-squash revision). They were collected before the complete-drain fix, removal of configuration knobs, and removal of event-type exemptions, not against the final PR commit. The coalescing limits were 64 events and 16 ms in the measured candidate, matching the final constants; the final implementation has not been remeasured.Method: Linux x64, Release
net11.0engines, identical benchmark-only probes around task-start/task-finish logging, notification calls, consumer callbacks, and flush waits. Both variants used the same SDK host and aligned runtime dependencies. The probes are not part of this PR.The workload was a local
dotnet/runtimestatic-graph restore ofBuild.projthroughNuGet.Build.Tasks.Console.dll, withMSBUILDLOGASYNC=1, no binary logger, and MSBuild server/node reuse disabled. After warmups, 20 measured restores ran in balanced control/candidate/candidate/control order: 10 per variant.Every run matched 1,643 projects, 16,060 task starts and finishes, 8,215
CheckForDuplicateNuGetItemsTaskinvocations, and 114,168 queued and drained events. Runs checked successful restore output, exit status, loaded-engine identity, and metric completeness. The runtime checkout had pre-existing local changes; its build-input fingerprint was checked before and after every run.CheckForDuplicateNuGetItemsTask(us/task)The paired mean saving in combined logging was 61.996 us/task (95% CI: 59.290-64.702 us/task). The paired mean wall-time saving was 2.560 s (95% CI: 1.321-3.799 s).
The task-logging numbers measure producer elapsed latency, not task CPU time. Total CPU and peak RSS differences were not statistically clear. Measured aggregate flush wait increased from 1.401 to 1.797 ms per restore; this describes the earlier drain implementation, not the final complete-drain path.
Dependencies and Follow-up
None. Benchmark instrumentation and generated artifacts are excluded from the PR.