Out-of-proc task hosts (and worker nodes) send one IPC packet per log message (~77us/log, ~13-25x in-proc); batching gives ~13x / up to 2x wall
- Dominant language
- C#
- Stars
- 5.5k
- Forks
- 1.5k
- Avg merge
- 1d 8h
- Merged PRs (30d)
- 141
Description
## Summary
When a task runs out-of-process (a `-mt` sidecar .NET task host, **or** a regular `-m` worker node), **every log event it emits is shipped to the parent as its own IPC packet**, each forced through the named pipe individually (`PipeOptions.WriteThrough`). There is no batching. Measured cost: **~77 µs per log message** in a .NET task host (~190 µs in a worker node), versus **~3 µs in-proc** — a **~13–25× penalty per log line**.
Additionally, the **.NET task host cannot filter by verbosity**: `OutOfProcTaskHostNode.LogsMessagesOfImportance` hardcodes `=> true`, so it forwards *every* guarded diagnostic message across the wire even when the build verbosity will discard it.
I prototyped the RAR node's batching approach for the task host and measured a **~13× drop in per-log cost** and a **1.9× wall-clock speedup (−48%)** on a log-heavy build. Details, data, and a proposed fix below.
## The cost, measured (per log message)
Isolated benchmark: a task that logs N=2000 messages, dispatched repeatedly; per-log overhead = (taskhost − nop_baseline)/N, median of 3.
| where the task runs | per-log µs | vs in-proc |
|---|---:|---:|
| **in-proc** (main node) | ~3 | 1× |
| **.NET task host** (nodemode:2, `-mt`) | **~77** | **~25×** |
| **worker node** (nodemode:1, `-m` + `MSBUILDNOINPROCNODE`) | **~190** | **~63×** |
This is **not CPU-bound** — sampled traces of both the task host and the parent show **>80% idle** even while pushing millions of messages. The cost is per-message **synchronization latency**: one packet → one `WriteThrough` pipe flush → one parent read-syscall → one route/wakeup, repeated per event.
### Root cause (code, all on `main`)
- One packet per event: `OutOfProcTaskHostNode.SendBuildEvent` does `new LogMessagePacketBase(...)` then `_nodeEndpoint.SendData(logMessage)` for **every** event. The worker-node path is equivalent via `BuildEventArgTransportSink.Consume` → one `LogMessagePacket` per event.
- Per-message flush: the shared child endpoint `NodeEndpointOutOfProcBase` creates the pipe with `PipeOptions.Asynchronous | PipeOptions.WriteThrough`, so each write flushes immediately.
- No source filtering in the task host: `OutOfProcTaskHostNode.LogsMessagesOfImportance(MessageImportance) => true`. It never receives the build's `MinimumRequiredMessageImportance`, so guarded diagnostic logging (the `if (Log.LogsMessagesOfImportance(...))` pattern that `TaskLoggingHelper` uses) always passes and ships everything. *(Worker nodes attach a `CentralForwardingLogger` and likewise forward everything, so they are not better here — they are worse on raw per-message cost.)*
The RAR out-of-proc node already solves the batching half of this: `RarNodeBufferedLogEvents` collects `List` and sends them as **one** packet.
## How much it costs a real build
Instrumenting `OutOfProcTaskHostNode.SendBuildEvent` to count events crossing the wire, an `OrchardCore.Cms.Web -t:Rebuild -mt` (`-v:m`) ships **23,504 log packets** from 16 task hosts. (The count is independent of verbosity, because the task host can't filter.)
- Theoretical saving from batching: 23,504 × (77.7 − 5.9) µs ≈ **1.69 s summed** across task hosts.
- On this *compile-bound* build (~105 s wall, task-host concurrency ≈ 6), that is ≈ **0.3 s wall (~0.3%)** — real but below run-to-run noise.
The win scales with **how much of wall time is logging**. Compile-bound builds barely notice; **chatty / restore-heavy / many-small-task builds** (where tiny tasks dispatch thousands of times and the result packet waits behind the task's log packets) pay it heavily.
## Validation of the fix
I implemented batching for the task host behind an env flag (`MSBUILDTASKHOSTLOGBATCH=`): a new `TaskHostLogMessageBatch` packet coalescing `List`, flushed at a count threshold and before the task-complete packet. Correctness verified (all messages still delivered, in order).
**Per-log cost (diag verbosity, 2000 logs/call, median of 3):**
| batch size | per-log µs | speedup |
|---|---:|---:|
| OFF (current) | 77.7 | 1.0× |
| 16 | 8.5 | 9.1× |
| 64 | 6.0 | 13.0× |
| 256 | 5.9 | 13.2× |
Batching brings task-host logging (**5.9 µs/log**) to **in-proc parity** (~7.7 µs/log at the same verbosity). The residual ~5.9 µs is the irreducible per-message work (serialize body + deserialize + route); batching removes the ~72 µs of per-message pipe-flush/wakeup latency.
**End-to-end wall clock:**
| scenario | OFF | ON (batch 256) | saving |
|---|---:|---:|---:|
| OrchardCore.Cms.Web `-mt` Rebuild (compile-bound) | 108.2 s | 106.2 s | ~2 s (within noise — as predicted) |
| log-heavy build, 24k log events (logs on critical path) | 4.29 s | 2.23 s | **−48%, 1.92×** |
The log-heavy synthetic emits ~24k events (≈ the same volume as the OrchardCore build) but concentrated so logging dominates wall — representative of restore-graph / diagnostic / chatty-task workloads. There the fix is clearly worth ~2× wall.
## Proposed changes
1. **Batch log packets in the out-of-proc nodes** (the main fix). Coalesce events into a single packet like the RAR node's `RarNodeBufferedLogEvents`, with a count threshold **and** a time-based flush (so logs still stream during long tasks rather than only at task end). Apply to the `.NET task host` (`OutOfProcTaskHostNode`) and ideally the worker-node forwarding path (`BuildEventArgTransportSink`), which is even slower per message. Expected: ~13× per-message, up to ~2× wall on log-heavy builds; negligible regression on compile-bound builds.
2. **Let the task host filter by verbosity** (complementary). Add `MinimumRequiredMessageImportance` to `TaskHostConfiguration` and make `OutOfProcTaskHostNode.LogsMessagesOfImportance` honor it, so guarded diagnostic messages that the build verbosity would drop are never constructed or sent. This removes wasted messages entirely rather than shipping-then-dropping.
Both are low-risk and have a production precedent (the RAR node). I have a working batching prototype + benchmarks and am happy to turn it into a PR.
## Reproduction / methodology
- Per-log cost: a synthetic `ITask` logging N `BuildMessageEventArgs`, dispatched K times in one target via `TaskHostFactory` vs `AssemblyTaskFactory` vs a `MSBUILDNOINPROCNODE=1 -m` worker node; per-call wall, median of 3, node reuse disabled between runs.
- Log volume: counter on `SendBuildEvent`, dumped per task-host PID at process exit.
- Traces: `dotnet-trace` sampling of the task-host and parent processes during heavy logging (both ~80% idle → latency-bound, not CPU).
Happy to share the prototype patch and raw scripts.
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with OutOfProcTaskHostNode.SendBuildEvent and NodeEndpointOutOfProcBase, then compare the existing RarNodeBufferedLogEvents batching path. Trace the worker-node equivalent through BuildEventArgTransportSink. Done means ordered log delivery with count- and time-based flushing, task-complete flushing, and verbosity filtering via TaskHostConfiguration, validated against the described benchmarks.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- csharp
- Domain
- build-system, performance
- Issue type
- Feature
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Quiet
- Clarity
- Mostly clear
- Newbie friendliness
- 55/100