romanett
b25429bccc
Follows #4707 (replaces #4714, which closed when the #4707 branch was deleted). Profiling the client process under load showed per-request allocation spread over the channel write path, the response wait, per-chunk header encoders and an AES instance per message, plus a stack walk per service call. This PR removes them and extends the load harness to measure the client. ## Results Paired A/B against the #4707 head, the server work now on master (3 alternating rounds, medians, 20 sessions unless noted, workstation GC on both sides, 24-core machine). Client = the harness process, server = the reference server child. | Scenario | Throughput | p50 | p90 | Client CPU / op | Client alloc / op | Server alloc / op | |---|---|---|---|---|---|---| | Read, 1 value | **+21%** (141k → 170k req/s) | −9% | −11% | −13% | −46% (4.5 → 2.4 KB) | −20% | | Read, 1 value, ManagedSession | **+18%** | −9% | −12% | −18% | −44% | −20% | | Read, 1 value, SignAndEncrypt | **+28%** | −14% | −20% | −24% | −52% | −26% | | Read, 1 value, 200 sessions | **+29%** | −11% | −17% | −17% | −46% | −20% | | Read, 100 values | +5% | −2% | −3% | −6% | −44% (15.6 → 8.8 KB) | −2% | | Read, 100 values, SignAndEncrypt | +8% | −7% | −2% | −2% | −46% | −3% | | Write, 100 values | ±0 | ≈ | ≈ | −14% | **−63%** (10.8 → 4.0 KB) | −2% | | Browse (Server object) | **+12%** | −7% | −11% | −19% | −17% | −12% | | Data changes, classic fast callback | ±0 ¹ | ≈ | ≈ | −21% | −10% | −5% | | Data changes, classic item events | ±0 ¹ | ≈ | ≈ | ≈ ² | −7% | −5% | | Data changes, ManagedSession (V2) | ±0 ¹ | ≈ | ≈ | ±0 | −5% | −5% | | Data changes, SignAndEncrypt | ±0 ¹ | ≈ | ≈ | −22% | −14% | −7% | ¹ Throughput is bounded by the writer rate; latency is dominated by the 100 ms publishing interval. Per notification the client uses about 2 µs and 170–260 B. ² The client uses 0.2–0.4 cores in the subscription scenarios; the CPU per notification is within run-to-run noise there. Client GC pause time in the window drops 38–66% in the Read and Write scenarios (17% for Browse). About 70% of the remaining client CPU per small request is kernel time in loopback socket send/receive. ## Changes - **Activity source**: `Session`, `SessionClientBatched`, the classic `Subscription` and `ClassicSubscriptionEngine`, and the TCP/HTTPS client channels resolve their `ActivitySource` once. `TelemetryExtensions.StartActivity` called `Assembly.GetCallingAssembly()` (a stack walk) on every service call, ~8% of client CPU. - **Channel write queue** (`UaSCUaBinaryChannel`, client and server): an ordered queue drained by one thread-pool writer replaces the per-write `ContinueWith`/`Unwrap`/trailing continuation chain. The writer is queued to the issuing thread's local pool queue, like the task continuation was (queuing it globally cost ~15 µs of p50 in a first iteration). Successful writes are reported inline instead of through `Task.Run`; failed writes still go through the pool. The client channel enters its gate only for a failed write instead of on every write completion. - **`TcpByteTransport`**: no linked `CancellationTokenSource` when the caller's token cannot be cancelled (the channel always passes `None`); a single-chunk `BufferCollection` uses the `ReadOnlyMemory` send instead of the vectored `Task<int>` send; `PoolingAsyncValueTaskMethodBuilder` on .NET 6+ for the receive/send state machines; no closure per vectored send. - **`BinaryEncoder.GetNodeIdEncoding`**: `Convert.ToUInt32(uint, IFormatProvider)` bound to the `object` overload and `Convert.ToByte(enum, ...)` boxed the enum, two boxes per encoded NodeId. 44% of the client allocation of a 100-value Read; the server encodes NodeIds the same way. - **Symmetric chunk headers**: the 24 header bytes are written and read with `BinaryPrimitives` instead of a `MemoryStream` + `BinaryEncoder`/`BinaryWriter` (send) and `BinaryDecoder`/`BinaryReader` (receive) per chunk. A chunk too short for a field still gets the decoder's `BadDecodingError`. - **AES-CBC**: `ChannelToken` keeps one `Aes` per direction, used with the one-shot `EncryptCbc`/`DecryptCbc` on .NET 6+ (net48 reuses the instance and creates the transform). Previously every message created an `Aes`, imported the key (`BCryptImportKey`) and created a transform, ~15% of client CPU with SignAndEncrypt. The instance is taken out of the token while in use, so concurrent callers never share one. The public `CryptoUtils` overloads are unchanged. - **`ChannelAsyncOperation`**: `SendRequestAsync` waits on an internal task-free completion source instead of `EndAsync` (`TaskCompletionSource` + `Task` + `WaitAsync` promise + state machine); `EndAsync` registers cancellation instead of `WaitAsync(ct)`; the timeout timer uses a static callback; completing with `default(T)` shares a box. - **Session keep alive**: every good response called `Timer.Change` under the session lock, taking the timer queue lock. It now records the time; the timer callback defers itself to one interval after the last response, which is when the per-response reset made it fire. ### Behaviour notes - `TcpByteTransport.SendChunkAsync`/`ReceiveChunkAsync` return pooled `ValueTask`s on .NET 6+: like any `ValueTask` they must be awaited once. - A successful write's `HandleWriteComplete` now runs on the writer instead of a separate pool work item. Overrides outside the stack that block in it delay later writes on that channel. - The write itself no longer flows the caller's `ExecutionContext` (`Activity.Current` is not set inside the transport send). ## Harness (`perf/`) - `client-process:` and `client-per-op:` result lines; `--trace-side client` records the harness itself. - `--client managed` (ManagedSession, V2 engine) and `--callback item` (classic per-item events). - Classic fixture sessions no longer request diagnostics in every response (the server otherwise sends a `DiagnosticInfo` per notification). - `ab.sh`: `SCENARIOS`/`ROUNDS`/`OUT`, CRLF tolerant, defaults before the scenario (a `--sessions 200` scenario silently ran with 20 before); `client-scenarios.txt`; `ab-summary.ps1` reports client and server medians. - README notes two profile traps: `Monitor.Enter_Slowpath` in the sampled CPU profile without matching contention events (46 in 10 s here), and allocation ticks over-attributing small objects allocated after large arrays. ## Testing - New: `UaSCBinaryChannelWriteQueueTests` (order, one send at a time, never on the caller's stack, failures reported and later writes still sent, concurrent writers), `ChannelAsyncOperationWaitTests` (late/early completion, faults, cancellation, disposal, continuation off the completing thread, 2000-iteration completion/cancellation race, timeout), `CryptoUtilsAesCacheTests` (cached = fresh cipher text across IVs, round trips, concurrent users, token disposal), `TcpByteTransportTests` single/multi-buffer and cancellable sends, `SessionKeepAliveTests` keep-alive read exactly one interval after the last response. - After merging master: Core Stack 3571 passed, Client 2763 passed, 0 failed. - Before merging master, net10.0: Core Stack+Security 4680 passed; Client 2763; Sessions 849 (379 skipped); Server 8391; Subscriptions 643; all 0 failed. - Stress Contract+Integration: 5 failures, the same 5 on the unchanged #4707 head (`CertRotationContractTests`, `GateAndBypassTests`, `LeaseLifecycleTests`, `RetryBudgetEnforcementTests` reflection seam, `CertRotationLiveTests`), not caused by this PR. - net48 build of `UA.slnx` clean; `dotnet format whitespace` clean. ## Not changed (follow-ups) - Two `recv` calls per chunk (8-byte header, then body). Merging them needs read-ahead with carry-over, which the transport avoids so that idle peers do not hold receive buffers. - `ManagedSession` service wrappers add an async state machine and a reader lock per call (~200 B). - Generated responses allocate a discarded `ResponseHeader` (generator-wide, as noted in #4707). - Decoded `MonitoredItemNotification` objects and the V2 `DataValueChange[]` per message dominate notification allocation (`WithPoolNotifications` pools the latter). - Coalescing queued writes on one channel into one vectored send would cut syscalls under concurrent requests on a shared channel. 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com> Co-authored-by: Marc <marcschier@hotmail.com> Co-authored-by: Marc Schier <marcschier@users.noreply.github.com>
Performance tooling
Tools for measuring server and client latency, throughput and GC cost under load. They are not
part of the product build (not in UA.slnx) and target net10.0 only.
| Path | Purpose |
|---|---|
ServerLoadHarness/ |
Starts a reference server in a child process and drives load against it from the parent process, which is also the measured client. |
TraceAnalyzer/ |
Aggregates the dotnet-trace files the harness records (CPU, allocations, lock contention). |
ab.sh, ab-summary.ps1 |
Paired A/B runs of two harness builds, and the median summary. |
server-scenarios.txt, client-scenarios.txt |
The scenario lists used for the server and client comparisons. |
The server runs in its own process, so the server-side numbers (CPU, allocated bytes, GC count
and pause time, Monitor.LockContentionCount) exclude the load generator, and the same
counters taken in the parent process measure the client stack without the server. The NUnit
LoadTest fixture in tests/Opc.Ua.Sessions.Tests checks correctness under load; this harness
measures it.
Build
CustomTestTarget=net10.0 dotnet build perf/ServerLoadHarness -c Release
dotnet build perf/TraceAnalyzer -c Release
dotnet tool install -g dotnet-trace
Run
perf/ServerLoadHarness/bin/Release/net10.0/ServerLoadHarness.exe run --scenario read --nodes 100 --sessions 20 --duration 15 --warmup 8
| Option | Default | Meaning |
|---|---|---|
--scenario |
read |
read, write, browse (Server object) or sub (data-change subscriptions plus a writer). |
--sessions |
20 | Concurrent sessions. |
--nodes |
100 | Values per Read/Write request, or monitored items per subscription. |
--inflight |
1 | Outstanding requests per session (closed loop). |
--security |
none |
none, sign or encrypt (Basic256Sha256). |
--client |
classic |
classic: Session with the classic subscription engine. managed: ManagedSession with the V2 subscription engine (DefaultSubscriptionEngineFactory). |
--callback |
fast |
Classic data changes through Subscription.FastDataChangeCallback (fast) or the per-item MonitoredItem.Notification event (item). |
--subs, --pub, --write-interval |
5, 100, 100 | Subscriptions per session, publishing interval and writer interval in ms (sub). |
--duration, --warmup |
20, 10 | Measurement window and warm-up in seconds. |
--diag, --audit |
0 | Server diagnostics and auditing. |
--trace <file> |
Record the measurement window with dotnet-trace. |
|
--trace-profile |
cpu |
cpu (sampled thread time), alloc (allocation ticks), contention or gc. |
--trace-side |
server |
The process to record: server (the child) or client (the harness itself). |
--out <file> |
Append the result block to a file. |
Environment variables prefixed SERVER_ are passed to the server process without the prefix,
for example SERVER_DOTNET_gcServer=1 to compare garbage collector modes. DOTNET_gcServer=1
set for the harness itself switches the client.
Managed subscription setup has a one-minute deadline per subscription. Rejected monitored items and subscription error or deletion states fail the scenario instead of waiting indefinitely or starting a measurement with incomplete subscriptions.
The result block reports client throughput and latency percentiles, the deltas of both
processes for the window (server:, client-process:), and the allocated bytes and CPU time
per request (or per notification) of the server (per-op:) and of the client
(client-per-op:). Classic sessions are created without diagnostics in responses, as an
application would; the test fixture otherwise asks for them. Allocated bytes per operation are
deterministic and the most reliable signal. On a shared machine, throughput and latency vary
from run to run, so compare builds with ab.sh rather than with two separate runs.
Analyse a trace
dotnet perf/TraceAnalyzer/bin/Release/net10.0/TraceAnalyzer.dll alloc trace.nettrace 40
dotnet perf/TraceAnalyzer/bin/Release/net10.0/TraceAnalyzer.dll cpu trace.nettrace 40 Monitor.Enter_Slowpath
dotnet perf/TraceAnalyzer/bin/Release/net10.0/TraceAnalyzer.dll contention trace.nettrace 15
The sampled thread-time profile also samples blocked threads. The cpu mode drops samples
whose leaf frame is a known wait (thread-pool semaphore, I/O completion poll, GC suspension),
so the remaining samples approximate on-CPU time. Spin-waiting in Monitor.Enter_Slowpath or
Lock.TryEnterSlow is real CPU and shows up there; check it against a contention trace,
though, because a thread blocked in the native part of Monitor.Enter has the same leaf frame.
Socket sends and receives on loopback show up as on-CPU kernel time.
The alloc profile samples one allocation per ~100 KB and attributes the whole sample to the
object that crossed the threshold. That over-weights small objects allocated right after large
arrays, so read the type list as a pointer and the per-operation bytes in the result block as
the measurement.
A/B comparison
Build the baseline harness in a second worktree, then alternate the two builds. SCENARIOS
selects the scenario list (server-scenarios.txt by default, client-scenarios.txt for the
client), ROUNDS the rounds per scenario and OUT the result file:
git worktree add --detach C:/uabase origin/master
cp -r perf C:/uabase/ && (cd C:/uabase && CustomTestTarget=net10.0 dotnet build perf/ServerLoadHarness -c Release)
cd perf && BASELINE=C:/uabase/perf/ServerLoadHarness/bin/Release/net10.0/ServerLoadHarness.exe SCENARIOS=client-scenarios.txt ./ab.sh
pwsh -File ab-summary.ps1
The summary prints medians as
baseline -> candidate (change): throughput, latency percentiles, client allocated bytes and CPU
per operation (calloc, ccpu), GC pause and lock contention in the window (cpause,
ccont), and the same for the server (alloc, cpu, pause, cont).