Investigation: loggingservice queue size creating contention in RAR in -mt

Problem

On an incremental no-op OrchardCore solution build, ResolveAssemblyReference (RAR) has substantially higher cumulative elapsed task time with -mt than without it. Profiling identifies producer blocking in the bounded LoggingService event queue while RAR emits reference-detail messages.

This is a logging-throughput/backpressure investigation, not evidence that assembly resolution itself becomes five times more expensive. Task durations include logging waits and overlap across parallel tasks; the MT build still completes faster overall.

Reproduction

Measured on Windows x64 with 16 logical processors:

MSBuild upstream commit a5ccf86e, built locally with -c Release; version 18.13.0-dev.26506.1+a5ccf86e1.
Bootstrap SDK 11.0.100-rc.1.26420.103. This is a locally built upstream bootstrap, not released MSBuild.
Clean OrchardCore checkout at ea88aa0e, built in Release.
Restore performed separately; MSBUILDUSESERVER=0 and node reuse disabled.

Using the bootstrap dotnet.exe, run the following twice without changing inputs, then twice with -mt, using a distinct binlog filename for every invocation:

$env:MSBUILDUSESERVER = '0'
& $bootstrapDotnet msbuild OrchardCore.slnx -t:Build -p:Configuration=Release -m -nr:false -v:quiet -bl:<unique-path>
# Repeat with the same options plus -mt.

Compare the second build in each mode. Both measured builds succeeded with 239 projects, no warnings/errors, no Csc invocations, and 237 RAR invocations.

Metric	Without `-mt`	With `-mt`
Process wall time	48.70 s	36.29 s
Cumulative RAR task elapsed time	12.935 s	65.548 s
Mean RAR task elapsed time	54.58 ms	276.57 ms

The binlog command lines prove -mt is absent/present respectively. The MT binlog also records "Multi-threaded strict mode is enabled."

Investigation scope

The default queue capacity is 200,000 events. When it fills, producers wait in LoggingService.ProcessLoggingEvent until the logging consumer makes room. In MT mode, concurrent tasks feed the shared queue directly. Console verbosity quiet does not suppress the detailed events requested by the binary logger.

Increasing MSBUILDLOGGINGQUEUECAPACITY to 2,000,000 substantially reduces cumulative RAR time in local runs. This is an experimental mitigation, not yet a production recommendation: more buffering can increase memory use and shift waiting to queue draining without improving sustained consumer throughput.

Questions and exit criteria

Quantify queue occupancy, blocked-producer time, logging-drain time, peak memory, and GC behavior under representative workloads.
Assess binary-log serialization, task-item/metadata payloads, and per-event signaling as throughput costs; distinguish burst pressure from sustained saturation.
Compare the current default with larger capacities in both MT and non-MT builds, including repeated no-op and non-incremental builds.
Determine whether the right fix is capacity tuning, lower event-production cost, faster draining/serialization, or a combination, without losing diagnostic information.
Validate memory/performance tradeoffs remotely before proposing a new default.

Experimental branch: perf/binlog/queue-experiment, commit 5143dd686. It changes only the default capacity from 200,000 to 2,000,000, retaining the environment override. The branch matches the performance pipeline's perf/* trigger; remote results are not included in the local conclusions below.

Local investigation conclusions

The inflated RAR elapsed time is predominantly logging-queue backpressure during LogResults, rather than assembly-resolution work. This conclusion is supported by both attributed thread stacks and controlled queue-capacity experiments.

Direct profiling evidence

A sampled-thread-time/EventPipe trace of an MT no-op build captured all 237 RAR executions with zero reported lost events:

RAR phase	Cumulative elapsed time
Overall RAR execution	65.132 s
`LogResults`	48.057 s
`ComputeClosure`	8.752 s

LogResults accounts for approximately 73.8% of overall RAR execution. About 79.9% of samples whose stacks include RAR were waiting. These are sampled thread-time observations, not CPU utilization percentages.

The observed blocking stack is:

ResolveAssemblyReference.LogResults
  -> LogReference (LogFullName / LogPrimaryOrDependency / LogCopyLocalState)
  -> TaskLoggingHelper.LogMessage
  -> TaskHost.LogMessageEvent
  -> LoggingService.LogBuildEvent
  -> LoggingService.ProcessLoggingEvent
  -> WaitHandle.WaitOne

The producer wait corresponds to the queue-full check in LoggingService.cs:

while (eventQueue.Count >= _queueCapacity)
{
    dequeueEvent.WaitOne();
}

A single logging pump processes an event through the loggers and then signals _dequeueEvent. Its active sampled stacks prominently include BinaryLogger / BuildEventArgsWriter, task-item and metadata serialization, record writing, GC polling, and per-event SetEvent calls. The consumer is not saturated throughout the entire build; producer stacks establish queue-full blocking during execution bursts. This does not isolate one serializer method as the sole root cause.

Controlled experiments

The following are separate successful MT no-op runs of the same restored solution. They retain the binlog, Release configuration, -m, -nr:false, and MSBUILDUSESERVER=0.

Run	Queue capacity	Cumulative RAR task time	Process wall time
Original MT measurement	200,000	65.548 s	36.29 s
Larger queue	2,000,000	18.513 s	30.94 s
RAR detail logging suppressed (`ResolveAssemblyReferencesSilent=true`)	200,000	17.762 s	31.83 s
Repeat: default	200,000	88.262 s	36.20 s
Repeat: larger queue	2,000,000	17.240 s	30.92 s
Repeat: default again	200,000	67.991 s	32.41 s

Returning to the default capacity after the larger-queue run restores the elevated RAR timings, reducing the likelihood that the improvement is just run-order warming. The initial comparison against non-MT had one measured second build per mode in fixed order; it should not be treated as a statistically established overall speedup.

Interpretation and limits

The local evidence establishes bounded-queue producer blocking as the principal cause of the RAR elapsed-time inflation. It does not demonstrate a fivefold increase in RAR CPU work.
Summed task durations overlap. A reduction of tens of seconds in cumulative RAR waits produces a much smaller end-to-end improvement.
A larger queue absorbs event bursts and reduces producer blocking, but costs buffering memory and can move waiting outside task execution. Peak memory, GC impact, and sustained logger throughput have not been quantified.
ResolveAssemblyReferencesSilent=true is a diagnostic experiment that removes RAR detail output, not a proposed default: reducing observability is not an equivalent production fix.
Optimize or measure event production and the logging-drain/serialization path before deciding that a 10x larger default is appropriate.

Remote experiment and validation

Pushed 5143dd686 to perf/binlog/queue-experiment. The only source change is DefaultQueueCapacity = 2000000; MSBUILDLOGGINGQUEUECAPACITY remains available. The branch matches the experimental performance pipeline trigger. Remote run completion/results have not been verified in this investigation.

Local checks after the source change:

.\build.cmd -c Release -msbuildEngine dotnet -v quiet -binaryLog -binaryLogName queue-experiment.binlog: passed, zero warnings/errors.
Bootstrap dotnet running Microsoft.Build.Engine.UnitTests.dll --filter-class '*LoggingService*' --no-progress: passed, 141 tests, zero skipped.
OrchardCore MT no-op build with the rebuilt bootstrap and no queue-capacity override: passed.

Retained local evidence includes the original four build binlogs, the attached MT .nettrace, per-experiment binlogs, exact mode evidence, and structured timing/trace summaries. These files have not been uploaded to this issue; the tables above report their relevant findings.

@baronfel

Mentioned offline:

Additionally, it would be interesting to find out why @baronfel's PRs didn't help with categorizing them and reducing the number of messages to send. I would have expected those 619k would go down to a reasonable number with those changes.

Investigation handoff: backpressure, useful-work overlap, and what to measure next

Established: the bounded asynchronous logging queue blocks RAR producers in MT builds, and increasing capacity substantially reduces those waits in this workload.

Working model, not yet a quantified critical-path attribution: blocking tasks can prevent dependent projects from starting, reducing overlap between build execution and logging. The same useful event processing can therefore take longer end-to-end. Increasing buffering does not necessarily make the logging consumer faster.

Not established: an optimal production capacity, zero observer effect, a single dominant consumer function, or the exact wall-time contribution of signaling, lost overlap, serialization, compression, and GC.

1. Source-confirmed mechanics

The asynchronous pipeline is:

Concurrent task/engine producers
  -> queue of BuildEventArgs objects (or routed event wrappers)
  -> one LoggingService pump
  -> warning/error handling, filtering/routing, synchronous logger callbacks
  -> BinaryLogger / BuildEventArgsWriter
  -> buffered gzip output

Queue entries are unfinished logging work, not already-encoded bytes. Some events carry item lists and metadata; event count is not a byte/memory-size bound.
In LoggingService.ProcessLoggingEvent, a producer waits on _dequeueEvent while eventQueue.Count >= _queueCapacity.
The pump removes an event, calls LoggingEventProcessor, and then signals _dequeueEvent. It continues processing while events exist; it does not sleep between every event.
Logger callbacks run synchronously on this delivery path. One slow callback can reduce the shared pump's throughput.
BinaryLogger.Write serializes under its writer lock. The writer performs event-specific encoding and string/metadata deduplication. Output already uses a 32 KiB buffer feeding gzip.
FlushRecordToFinalStream transfers an encoded record to that output stream. It is not a physical disk flush per message.
Build completion waits for outstanding logging to be processed. The cost has not disappeared if tasks finish sooner.

Source entry points at the experiment's base:
LoggingService.cs,
BinaryLogger.cs,
and BuildEventArgsWriter.cs.

2. Why unchanged useful work can still produce different wall time

A task that blocks while logging cannot return and unlock its dependent build work. Buffering can allow that work to proceed while logging catches up. This is a pipeline/critical-path effect, not necessarily a reduction in serialization CPU work.

Blocking/waking, capacity checks, contention, and memory/GC effects can also change total overhead, even if the useful event payloads are identical. Conversely, lower non-MT RAR durations do not prove lower total logging cost: forwarding/IPC and local versus central queues can place waiting outside the task interval being inspected.

These explanations are consistent with the observed queue waits and capacity response. We have not measured the exact seconds attributable to lost overlap or compared all non-MT backpressure locations. Do not treat an illustrative pipeline explanation as a measured critical-path result.

3. Updated measurements with daily Roslyn

The earlier measurements used pinned Roslyn 5.12. A later cohort used:

Windows x64, 16 logical processors.
Release MSBuild at 5143dd686, whose default capacity is experimentally 2M.
Daily SDK 11.0.100-rtm.26480.113, SDK/VMR commit 1764f3933fefec396a352f4472a7781d96bb88d4; Roslyn tasks/compiler 5.13.0-1.26480.113.
OrchardCore commit ea88aa0e, unchanged source, Release, restore excluded.
-m -nr:false -v:quiet, binlog enabled, MSBUILDUSESERVER=0. Explicit 200k override for the two baseline modes; compiled 2M default for MT+larger-queue.
Each mode warmed up; two measured repetitions in forward/reverse order. All six measured runs had 237 RAR invocations and zero Csc invocations.

Metric, mean of two runs	No MT, 200k	MT, 200k	MT, 2M
Process wall time	46.29 s	32.99 s	28.63 s
Cumulative RAR elapsed time	8.26 s	70.49 s	18.78 s
Cumulative GenerateMSBuildEditorConfig	0.21 s	0.27 s	0.27 s
Cumulative CopyRefAssembly	0.17 s	0.32 s	0.30 s

The larger queue's observed wall-time reduction versus MT+200k was 13.2% in this small cohort. This is not a statistical guarantee. Task totals overlap and are not CPU or critical-path time.

The substantial editor-config/reference-copy overhead seen with the pinned Roslyn payload disappeared in the daily-SDK cohort. Do not pursue those old timings as evidence of a remaining queue bottleneck.

Bootstrap pitfall: the normal bootstrap overlay copied pinned Roslyn over the daily SDK's Roslyn. The final measured bootstrap explicitly preserved the daily Roslyn directory/targets and aligned SDK dependency files while overlaying the local MSBuild binaries. Verify actual file product versions, task assembly paths in the binlog, SDK selection, and dotnet msbuild -version; SDK metadata alone is insufficient.

4. Event volume and residual overhead

Raw binlog records attributed by RAR task context, identical across the three daily modes:

340,974 ordinary BuildMessageEventArgs records.
6,848 task input/output parameter records.
347,822 total RAR-context message events, about 36% of roughly 959k build message events.

These are event records, not expanded viewer lines, metadata-value counts, or necessarily messages originating exclusively in LogResults. The comment mentioning 619k has not been reconciled with this count; do not compare counts without matching scope, toolset, logger configuration, and event types. These builds retained a diagnostic binary logger despite quiet console output. The categorization/filtering changes mentioned above have not been isolated experimentally; these counts do not establish that those changes failed.

A separate daily MT+2M profile recorded 237 RAR executions with no reported lost events:

Observation	Value
Cumulative RAR overall	18.09 s
Cumulative closure computation	8.15 s
Cumulative LogResults	1.24 s
RAR stack samples showing logging-queue waits	4 / 4,099
Estimated overlap with runtime GC/GC-preparation suspension	4.81 s

Residual stacks included cache-file reads, file attributes/timestamps, path normalization, and item-metadata construction. The suspension-overlap estimate is included in RAR time, not additive; unrelated SuspendOther intervals were excluded. Profiling can perturb execution. No matched non-MT GC profile was collected, so this does not explain the entire remaining MT/non-MT gap or prove that a larger queue caused the GC activity.

Correction to the earlier comment's 79.9% waiting figure: its broad stack-name matcher also included EventWaitHandle.Set. Restricting the original trace to actual wait calls under ProcessLoggingEvent gives 19,457 / 24,629 RAR samples = 79.0%. The queue-blocking conclusion is unchanged; neither percentage is CPU utilization.

5. Queue-depth histogram and observer-effect limits

An additional local instrumented build collected three verified no-op MT runs per capacity. It added no per-event counters, callbacks, allocations, or branches to the enqueue/dequeue paths.

The dedicated sampler made bounded volatile reads of private queue segment indices: no ConcurrentQueue.Count, queue locks, segment freezing, or stability retries. It stored depth bounds and monotonic timestamps in preallocated buffers; CSV output occurred only after the logging pump stopped. Unsupported runtime layout fails explicitly. This reflective experiment is excluded from normal builds and is not trim/AOT-compatible.

Nominal cadence was 50 ms; actual median approximately 63 ms, with a largest gap of 1.35 s. Histograms weight actual intervals using the preceding sample. This cannot reconstruct depth changes during gaps or prove an exact unsampled maximum.

Depth band, percent of active logging-service lifetime including draining	200k	2M
Empty	12.20%	6.64%
1-50k	24.21%	15.80%
50k-150k	12.55%	15.88%
150k-190k	4.59%	3.83%
190k-210k	46.21%	1.89%
210k-500k	0%	53.54%
500k-1M	0%	2.42%

Sampled peaks were 200,001-200,002 and 515,609 events. There were 1,481/1,278 active-queue samples, no invalid transition samples or buffer overflow, and maximum depth-bound widths of 20/144 events. About 0.23% of 200k observation time straddled bucket boundaries and was not assigned to a bucket; negligible unsampled startup is also excluded. A separate always-empty evaluation queue was not mixed into the active build queue. Small capacity overshoots are possible because checking capacity and enqueueing are not an atomic reservation.

All depth reads, including the idle queue, consumed approximately 0.023% of elapsed observation time. This does not include all initialization, wakeup, scheduling, allocation, or GC effects.

At 200k, three verified no-op controls averaged 33.42 s with sampling off versus 33.73 s on (+0.91%). Too few runs to establish zero observer effect.
At 2M, all four attempted sampling-off controls recompiled OrchardCore.Mvc.Web and OrchardCore.Tests.Functional after assembly-info regeneration. They were excluded. The end-to-end 2M observer-effect comparison remains blocked.
All six sampled runs themselves had zero Csc invocations. Nevertheless, the scheduling/recompilation asymmetry is an unresolved confounder, not proof that instrumentation is harmless. Investigate it rather than assuming it away.

6. Batching: promising directions versus misleading shortcuts

Moving the entire queue into a list can free queue capacity quickly, but does not finish the work. It relocates backlog, permits additional accumulation, and can make queue-depth statistics look better while increasing retained memory. Account for queued plus in-flight work when evaluating this approach.

Bounded batching may genuinely reduce per-event queue/writer-lock/signaling costs. It still has to preserve event processing and delivery semantics. In particular:

_dequeueEvent is an auto-reset event: one Set does not wake every blocked producer. Batch release needs a correct capacity/wakeup protocol.
Preserve serialized logger callbacks, relevant event ordering/context, warning/error handling, and completion/drain guarantees. Do not assume custom loggers are thread-safe.
Binary output is already byte-buffered; eliminating a supposed per-message disk flush is not the demonstrated opportunity.
Deferring encoding or parallelizing preparation requires auditing payload lifetimes/mutability and the writer's ordered string/metadata-record state.
Reducing or compacting RAR diagnostics is a separate compatibility/observability change. ResolveAssemblyReferencesSilent=true was a diagnostic experiment, not a proposed default.

7. Suggested investigation sequence

Establish repeatable no-op controls, especially the unexplained 2M recompilation asymmetry. Validate every binlog, not just successful exit codes; record compiler invocations and input/output changes.
Separate arrival rate, processing rate, producer-blocked time, task/critical-path delays, and final logging-drain time. Queue-depth histograms alone cannot distinguish all of these.
Measure consumer exclusive CPU, serialization payload volume, signaling/syscall cost, allocations/GC, and memory retention. Separate profiler-induced suspension from GC/GC-preparation suspension.
Test one change at a time: bounded drain/signaling batches, serializer improvements, or compact structured diagnostics. Include queued/in-flight work and verify preserved event payloads/order.
Compare whole-process wall time, memory, and diagnostic fidelity across multiple workloads, both MT and non-MT. A lower RAR total or prettier queue histogram is not sufficient success criteria.

Reproduction and availability

Use a fixed daily SDK/Roslyn payload and local Release MSBuild; restore separately, warm each mode, and measure repeated builds with identical inputs:

$env:MSBUILDUSESERVER = '0'
$env:MSBUILDLOGGINGQUEUECAPACITY = '200000' # compare with 2000000
& $bootstrapDotnet msbuild OrchardCore.slnx -t:Build -p:Configuration=Release -m -nr:false -v:quiet -mt -bl:<unique-path>
# For the non-MT comparison, omit -mt.

The capacity-only commit 5143dd686 is published on both
perf/binlog/queue-experiment
and perf/janpro/binlog-queue-attermpt2.
Remote pipeline results have not been verified in this handoff.

The queue sampler is local and uncommitted, not present on those remote branches. Its local build flag is /p:QueueDepthInstrumentation=true; its runtime opt-in is MSBUILDLOGGINGQUEUEDEPTHFILE=<absolute-prefix>. Do not expect those flags to collect samples from the published capacity-only branch.

Raw binlogs, traces, CSVs, and scripts have not been uploaded to this issue. Retained local artifacts include orchard-daily-comparison.json, orchard-daily-rar-message-counts.json, orchard-daily-mt-queue-trace-analysis.json, queue-depth-histogram.json/.svg, and queue-depth-build-summary.json; scripts include MakeDailyBootstrap.proj, Analyze-OrchardTrace.ps1, Count-RarMessages.ps1, Measure-QueueDepth.ps1, and Analyze-QueueDepth.py. The tables here are the portable evidence summary; obtain the raw artifacts or rerun before relying on finer-grained conclusions.

Use a reader supporting the recorded binlog format. The older local StructuredLogger reported unknown event records; task counts and approximate timing aggregates were cross-checked with the newer MCP reader. Such viewer compatibility notices are not build warnings.

@agocke

Separately I was talking to @agocke yesterday and he's independently found that the logger evening (the single manual reset event count resetting per message) is incredibly expensive and moving to batching would be a great direction for this service.

Mentioned offline:

Additionally, it would be interesting to find out why @baronfel's PRs didn't help with categorizing them and reducing the number of messages to send. I would have expected those 619k would go down to a reasonable number with those changes.

in my binlog there are not 619k but 350k RAR events and 960k total events. So perhaps it went down

Navigation Menu

Repository navigation

Investigation: loggingservice queue size creating contention in RAR in -mt #15224

Problem

Reproduction

Investigation scope

Questions and exit criteria

Local investigation conclusions

Direct profiling evidence

Controlled experiments

Interpretation and limits

Remote experiment and validation

Investigation handoff: backpressure, useful-work overlap, and what to measure next

1. Source-confirmed mechanics

2. Why unchanged useful work can still produce different wall time

3. Updated measurements with daily Roslyn

4. Event volume and residual overhead

5. Queue-depth histogram and observer-effect limits

6. Batching: promising directions versus misleading shortcuts

7. Suggested investigation sequence

Reproduction and availability

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Investigation: loggingservice queue size creating contention in RAR in -mt #15224

Description

Problem

Reproduction

Investigation scope

Questions and exit criteria

Activity

JanProvaznik commented on Oct 7, 2026

Local investigation conclusions

Direct profiling evidence

Controlled experiments

Interpretation and limits

Remote experiment and validation

ViktorHofer commented on Oct 7, 2026

JanProvaznik commented on Oct 8, 2026

Investigation handoff: backpressure, useful-work overlap, and what to measure next

1. Source-confirmed mechanics

2. Why unchanged useful work can still produce different wall time

3. Updated measurements with daily Roslyn

4. Event volume and residual overhead

5. Queue-depth histogram and observer-effect limits

6. Batching: promising directions versus misleading shortcuts

7. Suggested investigation sequence

Reproduction and availability

baronfel commented on Oct 8, 2026

JanProvaznik commented on Oct 8, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions