mirror of
https://github.com/OPCFoundation/UA-.NETStandard.git
synced 2026-10-17 05:11:13 +08:00
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>
40 lines
2.2 KiB
PowerShell
40 lines
2.2 KiB
PowerShell
param($file = "ab-results.txt")
|
|
# Medians per scenario and side of the result blocks that ab.sh appends.
|
|
# alloc/cpu/pause/cont are server-side, calloc/ccpu/cpause/ccont client-side.
|
|
$rows = @()
|
|
$cur = $null
|
|
foreach ($l in Get-Content $file) {
|
|
if ($l -match '^### side=(\w) round=(\d+) (.*)$') { $cur = @{ side = $Matches[1]; scen = $Matches[3].Trim() }; continue }
|
|
if ($null -eq $cur) { continue }
|
|
if ($l -match '^\s+client: ') {
|
|
if ($l -match 'req/s=(\d+)') { $cur.tput = [double]$Matches[1] }
|
|
if ($l -match 'notif/s=(\d+)') { $cur.tput = [double]$Matches[1] }
|
|
if ($l -match 'p50=([\d.]+)ms p90=([\d.]+)ms p99=([\d.]+)ms') { $cur.p50 = [double]$Matches[1]; $cur.p90 = [double]$Matches[2]; $cur.p99 = [double]$Matches[3] }
|
|
}
|
|
elseif ($l -match '^\s+server: ') {
|
|
if ($l -match 'pauseMs=(\d+)') { $cur.pause = [double]$Matches[1] }
|
|
if ($l -match 'contention=(\d+)') { $cur.cont = [double]$Matches[1] }
|
|
}
|
|
elseif ($l -match '^\s+client-process: ') {
|
|
if ($l -match 'pauseMs=(\d+)') { $cur.cpause = [double]$Matches[1] }
|
|
if ($l -match 'contention=(\d+)') { $cur.ccont = [double]$Matches[1] }
|
|
}
|
|
elseif ($l -match '^\s+per-op: allocB=(\d+) cpuUs=([\d.]+)') { $cur.alloc = [double]$Matches[1]; $cur.cpu = [double]$Matches[2] }
|
|
elseif ($l -match '^\s+client-per-op: allocB=(\d+) cpuUs=([\d.]+)') {
|
|
$cur.calloc = [double]$Matches[1]; $cur.ccpu = [double]$Matches[2]
|
|
$rows += [pscustomobject]$cur; $cur = $null
|
|
}
|
|
}
|
|
function Med($xs) { $s = @($xs | Where-Object { $null -ne $_ } | Sort-Object); if ($s.Count -eq 0) { return [double]::NaN }; return $s[[int][Math]::Floor($s.Count / 2)] }
|
|
$out = @()
|
|
foreach ($g in ($rows | Group-Object scen)) {
|
|
$a = $g.Group | Where-Object side -eq 'A'; $b = $g.Group | Where-Object side -eq 'B'
|
|
$o = [ordered]@{ scenario = $g.Name; n = "$(@($a).Count)/$(@($b).Count)" }
|
|
foreach ($m in 'tput', 'p50', 'p90', 'p99', 'calloc', 'ccpu', 'cpause', 'ccont', 'alloc', 'cpu', 'pause', 'cont') {
|
|
$ma = Med ($a | ForEach-Object { $_.$m }); $mb = Med ($b | ForEach-Object { $_.$m })
|
|
$o["$m"] = "{0:G4} -> {1:G4} ({2:+0;-0}%)" -f $ma, $mb, (100 * ($mb - $ma) / $ma)
|
|
}
|
|
$out += [pscustomobject]$o
|
|
}
|
|
$out | Format-List
|