perf: client GC measurement, V2 client by default, container-like client constraints (#4844)

Extends the out-of-process load harness (`perf/`, not part of the
product build) so it can measure client-side GC, run the V2 client by
default, and emulate a container-sized client. No product code changes.

## Client GC measurement
- New `client-gc:` result line from an in-process GC event listener
(`GcListener.cs`, runtime GC keyword at informational level): GC mode,
collections by condemned generation and trigger, pause and suspension
p50/p99/max, bytes surviving gen0/gen1, pinned objects, gen2/LOH size,
peak heap after a collection, committed bytes, heap limit, DATAS heap
count and gen0 budget. `--gc-events 0` turns it off.
- The latency recorder is now a fixed log-linear histogram (~1.6 %
resolution). The old `ConcurrentBag<long>` kept ~25 MB of samples alive
in the measured client's gen2 (client heap 29–31 MB vs 4 MB now).
- **Fix:** GC, thread-pool and processor-count settings set for the
harness (`DOTNET_GC*`, `COMPlus_GC*`, `DOTNET_ThreadPool_*`,
`DOTNET_PROCESSOR_COUNT`) no longer leak into the server child. Before,
`DOTNET_gcServer=1` switched the server too, although the README said it
switched the client. `SERVER_`-prefixed variables still configure the
server.
- TraceAnalyzer `gc` decodes the condemn reasons and breaks each
collection into phases (marking by root type with the bytes marked,
plan/relocate/compact).

## V2 client by default
- `--client` defaults to `managed` (`ManagedSession` + V2 subscription
engine). The `events` and `counters` workloads gained V2 paths;
`--pool-notifications 1` enables `WithPoolNotifications`.
`client-scenarios.txt` lists V2 scenarios. `--client classic` and
`shared` still work.

## Container-like client
- `--client-cores N`: the harness runs itself again with
`DOTNET_PROCESSOR_COUNT=N` on the last N processors and pins the server
to the others.
- `--client-memory MB`: the client's GC heap hard limit becomes 75 % of
MB, the limit .NET derives from a container memory limit (native memory
is not capped).

## What it found
The report is published separately. Highlights:
- Request path: a gen0 pause costs ~1 ms of fixed work (stack and card
scanning, compaction), so pause time follows collection count. Read-1
allocates ~2 KB/request on the client, and its p99 is the GC pause (a 64
MB gen0 halves it).
- V2 subscriptions and events never reach gen2 (classic `Subscription`
with its message cache: 22 % of wall time paused for events).
- Containers: each V2 monitored item costs 2.8–3.8 KB, mostly a per-item
`ConcurrentDictionary` in `OptionsMonitor<T>` (one lock per processor)
and a per-item `ConcurrentQueue`. 100k items do not fit in a 256 MB
container. A 1-processor client stalls ~1 s unless the thread-pool
minimum is raised.

## Testing
- Harness builds in Release (`CustomTestTarget=net10.0`). I ran every
changed scenario: read/write/browse/sub/events/counters on managed
sessions, constrained runs with 1, 2 and 4 cores and 256 MB to 1 GB, and
`TraceAnalyzer gc/alloc` on recorded traces.

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
Co-authored-by: Marc Schier <marcschier@users.noreply.github.com>
Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com>
Co-authored-by: marcschier <11168470+marcschier@users.noreply.github.com>
This commit is contained in:
romanett
2026-10-20 09:44:26 +02:00
committed by GitHub
parent ad8c6ce59f
commit 4ae2395f37
8 changed files with 981 additions and 44 deletions
+32 -6
View File
@@ -37,8 +37,9 @@ perf/ServerLoadHarness/bin/Release/net10.0/ServerLoadHarness.exe run --scenario
| `--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`). `shared`: classic sessions on secure channels shared through one `ClientChannelManager`, created one at a time (`--connect-parallel`). |
| `--callback` | `fast` | Classic data changes through `Subscription.FastDataChangeCallback` (`fast`) or the per-item `MonitoredItem.Notification` event (`item`). |
| `--client` | `managed` | `managed`: `ManagedSession` with the V2 subscription engine (`DefaultSubscriptionEngineFactory`), used by `sub`, `events` and `counters`. `classic`: `Session` with the classic subscription engine. `shared`: classic sessions on secure channels shared through one `ClientChannelManager`, created one at a time (`--connect-parallel`). |
| `--pool-notifications` | 0 | 1: the V2 subscription manager recycles notification objects after the handler returns (`ManagedSessionBuilder.WithPoolNotifications`). |
| `--callback` | `fast` | Classic engine only: 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`). |
| `--write-nodes` | all | Number of the monitored nodes the writer changes (`sub`), for large subscriptions in which few items change. |
| `--writers` | 0 | Dedicated writer sessions in addition to `--sessions` (`sub`). 0: the first subscriber session writes. |
@@ -55,10 +56,14 @@ perf/ServerLoadHarness/bin/Release/net10.0/ServerLoadHarness.exe run --scenario
| `--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. |
| `--gc-events` | 1 | 0: turn the in-process GC event listener off (no `client-gc:` line). |
| `--client-cores` | all | Windows only. Confine the client like a container with N processors: the harness runs itself again with `DOTNET_PROCESSOR_COUNT=N` (thread pool, GC and `ConcurrentDictionary` sizing) on the last N of the processors it may use, and pins the server to the remaining ones. The process affinity mask applies to all threads on Windows but only to the main thread on Linux, so on Linux use a cgroup (`docker --cpuset-cpus`) or `taskset` instead. |
| `--client-memory` | unlimited | Container memory limit of the client in MB: the GC heap hard limit becomes 75 % of it, the limit .NET derives from a container memory limit. Only the managed heap is limited, not native memory. |
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.
for example `SERVER_DOTNET_gcServer=1` to compare garbage collector modes. GC settings set for
the harness itself (`DOTNET_GC*`, `COMPlus_GC*`, for example `DOTNET_gcServer=1` or
`DOTNET_GCgen0size=0x4000000`) configure only the client: the server child does not inherit them.
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
@@ -72,6 +77,20 @@ application would; the test fixture otherwise asks for them. Allocated bytes per
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.
The `client-gc:` line summarizes the client's collections in the window from the runtime's GC
events (an in-process `EventListener`, a few events per collection): the GC mode, the
collections by condemned generation and trigger (`gen2bg` is a background gen2), the number
of stop-the-world pauses with their percentiles and suspension percentiles (a background gen2
stops the threads more than once, so `pauses` can exceed `n`), the bytes that survived gen0 and gen1 per collection, the gen2 and LOH
sizes after the last collection, the largest heap left after a collection (`peakAfterGcMB`), the
committed bytes and the heap limit (`limitMB`, the hard limit under `--client-memory`), the heap
count DATAS chose and the gen0 budget. A
`survivedKB/gen0` close to the gen0 budget means objects outlive a gen0 collection, and the
collections turn into gen1 and background gen2 ones. `CollectionCount` in `client-process:`
counts a gen1 collection under both `gen0` and `gen1`; `client-gc:` counts each collection once.
Latencies are recorded in a fixed log-linear histogram (about 1.6 % resolution), so the
recorder neither allocates nor keeps samples alive in the measured client.
## External benchmark workers
`--scenario native-read` and `--scenario native-counters` drive a server with the native
@@ -170,8 +189,15 @@ dotnet perf/TraceAnalyzer/bin/Release/net10.0/TraceAnalyzer.dll threads trace.ne
above it, past framework wrappers such as `Monitor.Enter` or `SemaphoreSlim`, and the frame's
direct callees. `gc` reads a
trace recorded with `--trace-profile gc`, lists the collections by generation and trigger
reason and splits each pause into the time needed to suspend the threads and the whole pause;
a long suspension means a thread ran for a while without reaching a safe point. `samples`
reason, the condemn reasons the GC recorded (`condemn budget=gen1`: the gen1 budget was
exhausted), the average time per blocking collection of each phase (marking by root type with
the bytes marked from stacks, handles and old-generation cards, summed over the heaps of Server
GC, then plan/relocate/compact and restart as elapsed time; background gen2 collections and the
foreground ones inside them are left out of the phases) and splits each
pause into the time needed to suspend the threads and the whole pause; a long suspension means a
thread ran for a while without reaching a safe point. A pause that stays long while few bytes are
marked is the fixed cost of a collection (stack and card scanning), which only fewer collections
reduce. `samples`
lists all thread-time samples by type and leaf frame (and by the first `Opc.Ua` frame),
including the ones `cpu` leaves out.
+123
View File
@@ -34,6 +34,7 @@ using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;
using Opc.Ua.Client;
using V2 = Opc.Ua.Client.Subscriptions;
namespace Opc.Ua.Perf.ServerLoadHarness
{
@@ -64,6 +65,11 @@ namespace Opc.Ua.Perf.ServerLoadHarness
public override async Task SetupAsync()
{
ushort namespaceIndex = (ushort)m_session.NamespaceUris.GetIndex(CounterNodeManager.Namespace);
if (m_session is ManagedSession managed)
{
await SetupManagedAsync(managed, namespaceIndex).ConfigureAwait(false);
return;
}
#pragma warning disable CA2000 // ownership transfers to the session in AddSubscription; disposed below on failure before that
var subscription = new Subscription(m_session.DefaultSubscription)
{
@@ -156,6 +162,121 @@ namespace Opc.Ua.Perf.ServerLoadHarness
(below == 0 && missing == 0 ? "PASS" : "FAIL");
}
private async Task SetupManagedAsync(ManagedSession session, ushort namespaceIndex)
{
var setup = new SubscriptionSetup();
V2.ISubscription subscription = session.AddSubscription(
new NotificationHandler(this, setup),
new V2.SubscriptionOptions
{
PublishingInterval = TimeSpan.FromMilliseconds(m_publishingInterval),
PublishingEnabled = true,
KeepAliveCount = 10,
LifetimeCount = 10000,
MaxNotificationsPerPublish = 0
});
for (int i = 0; i < m_latestValue.Length; i++)
{
if (!subscription.TryAddMonitoredItem(
i.ToString(System.Globalization.CultureInfo.InvariantCulture),
new V2.MonitoredItems.MonitoredItemOptions
{
StartNodeId = new NodeId((uint)i + 1, namespaceIndex),
AttributeId = Attributes.Value,
MonitoringMode = MonitoringMode.Reporting,
SamplingInterval = TimeSpan.FromMilliseconds(m_samplingInterval),
TimestampsToReturn = TimestampsToReturn.Neither,
QueueSize = 1,
DiscardOldest = true
},
out V2.MonitoredItems.IMonitoredItem? item) || item == null)
{
throw new InvalidOperationException($"Could not add counter item {i}.");
}
// notifications can arrive while items are still being added
lock (m_lock)
{
m_indexByItem[item] = i;
}
}
var time = Stopwatch.StartNew();
await setup.WaitForReadyAsync(subscription, default).ConfigureAwait(false);
Console.WriteLine(FormattableString.Invariant(
$"counters: {m_latestValue.Length} items (V2), sampling {m_samplingInterval} ms, ") +
FormattableString.Invariant($"publishing {m_publishingInterval} ms; setup {time.ElapsedMilliseconds} ms"));
}
/// <summary>
/// V2 engine handler; updates the counters like the classic fast callback.
/// </summary>
private sealed class NotificationHandler : V2.ISubscriptionNotificationHandler
{
public NotificationHandler(CounterWorkload owner, SubscriptionSetup setup)
{
m_owner = owner;
m_setup = setup;
}
public ValueTask OnDataChangeNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
ReadOnlyMemory<V2.DataValueChange> notification,
V2.PublishState publishStateMask,
IReadOnlyList<string> stringTable)
{
long now = Stopwatch.GetTimestamp();
lock (m_owner.m_lock)
{
foreach (V2.DataValueChange change in notification.Span)
{
if (change.MonitoredItem != null &&
m_owner.m_indexByItem.TryGetValue(change.MonitoredItem, out int index) &&
change.Value.WrappedValue.TryGetValue(out ulong value))
{
m_owner.m_latestValue[index] = value;
m_owner.m_latestTicks[index] = now;
}
}
}
Interlocked.Add(ref m_owner.m_notifications, notification.Length);
return ValueTask.CompletedTask;
}
public ValueTask OnEventDataNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
ReadOnlyMemory<V2.EventNotification> notification,
V2.PublishState publishStateMask,
IReadOnlyList<string> stringTable)
{
return ValueTask.CompletedTask;
}
public ValueTask OnKeepAliveNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
V2.PublishState publishStateMask)
{
return ValueTask.CompletedTask;
}
public ValueTask OnSubscriptionStateChangedAsync(
V2.ISubscription subscription,
V2.SubscriptionState state,
V2.PublishState publishStateMask,
CancellationToken ct = default)
{
m_setup.OnStateChanged(state);
return ValueTask.CompletedTask;
}
private readonly CounterWorkload m_owner;
private readonly SubscriptionSetup m_setup;
}
private void OnDataChange(Subscription subscription, DataChangeNotification notification, ArrayOf<string> stringTable)
{
long now = Stopwatch.GetTimestamp();
@@ -178,6 +299,8 @@ namespace Opc.Ua.Perf.ServerLoadHarness
private readonly int m_samplingInterval;
private readonly int m_publishingInterval;
private readonly Dictionary<uint, int> m_indexByHandle = [];
private readonly Dictionary<V2.MonitoredItems.IMonitoredItem, int> m_indexByItem =
new(System.Collections.Generic.ReferenceEqualityComparer.Instance);
private readonly ulong[] m_latestValue;
private readonly long[] m_latestTicks;
private readonly ulong[] m_startValue;
+127 -15
View File
@@ -29,11 +29,13 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Globalization;
using System.Threading;
using System.Threading.Tasks;
using Opc.Ua.Client;
using V2 = Opc.Ua.Client.Subscriptions;
using IServerInternal = Opc.Ua.Server.IServerInternal;
namespace Opc.Ua.Perf.ServerLoadHarness
@@ -202,6 +204,11 @@ namespace Opc.Ua.Perf.ServerLoadHarness
private async Task CreateSubscriptionAsync(ISession session, CancellationToken ct)
{
if (session is ManagedSession managed)
{
await CreateManagedSubscriptionAsync(managed, ct).ConfigureAwait(false);
return;
}
#pragma warning disable CA2000 // ownership transfers to the session in AddSubscription; disposed below on failure before that
var subscription = new Subscription(session.DefaultSubscription)
{
@@ -213,20 +220,12 @@ namespace Opc.Ua.Perf.ServerLoadHarness
#pragma warning restore CA2000
try
{
var filter = new EventFilter();
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.EventId));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.EventType));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.SourceNode));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.SourceName));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Time));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Message));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Severity));
subscription.AddItem(new MonitoredItem(subscription.DefaultItem)
{
StartNodeId = ObjectIds.Server,
AttributeId = Attributes.EventNotifier,
MonitoringMode = MonitoringMode.Reporting,
Filter = filter,
Filter = CreateFilter(),
QueueSize = (uint)m_queueSize
});
session.AddSubscription(subscription);
@@ -239,6 +238,51 @@ namespace Opc.Ua.Perf.ServerLoadHarness
await subscription.CreateAsync(ct).ConfigureAwait(false);
}
private async Task CreateManagedSubscriptionAsync(ManagedSession session, CancellationToken ct)
{
var setup = new SubscriptionSetup();
V2.ISubscription subscription = session.AddSubscription(
new NotificationHandler(this, setup),
new V2.SubscriptionOptions
{
PublishingInterval = TimeSpan.FromMilliseconds(m_publishingInterval),
PublishingEnabled = true,
KeepAliveCount = 10,
LifetimeCount = 100
});
if (!subscription.TryAddMonitoredItem(
"events",
new V2.MonitoredItems.MonitoredItemOptions
{
StartNodeId = ObjectIds.Server,
AttributeId = Attributes.EventNotifier,
MonitoringMode = MonitoringMode.Reporting,
Filter = CreateFilter(),
QueueSize = (uint)m_queueSize
},
out _))
{
throw new InvalidOperationException("Could not add the event monitored item during subscription setup.");
}
await setup.WaitForReadyAsync(subscription, ct).ConfigureAwait(false);
}
/// <summary>
/// The select clauses of the Sessions <c>ServerEventSubscribeLoadTest</c>; Time is field 4.
/// </summary>
private static EventFilter CreateFilter()
{
var filter = new EventFilter();
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.EventId));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.EventType));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.SourceNode));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.SourceName));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Time));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Message));
filter.AddSelectClause(ObjectTypeIds.BaseEventType, QualifiedName.From(BrowseNames.Severity));
return filter;
}
private void OnEvents(Subscription subscription, EventNotificationList notification, ArrayOf<string> stringTable)
{
DateTime now = DateTime.UtcNow;
@@ -246,16 +290,84 @@ namespace Opc.Ua.Perf.ServerLoadHarness
foreach (EventFieldList fields in notification.Events)
{
count++;
// sample every 16th event so the recorder stays small at high rates
if ((count & 15) == 1 && fields.EventFields.Count > 4 &&
fields.EventFields[4].TryGetValue(out DateTimeUtc time))
{
m_latency.Record((long)((now - ((DateTime)time).ToUniversalTime()).TotalSeconds * Stopwatch.Frequency));
}
RecordLatency(now, count, fields.EventFields);
}
Interlocked.Add(ref m_events, count);
}
private void RecordLatency(DateTime now, int count, ArrayOf<Variant> fields)
{
// sample every 16th event so the recorder stays small at high rates
if ((count & 15) == 1 && fields.Count > 4 && fields[4].TryGetValue(out DateTimeUtc time))
{
m_latency.Record((long)((now - ((DateTime)time).ToUniversalTime()).TotalSeconds * Stopwatch.Frequency));
}
}
/// <summary>
/// V2 engine handler; events are counted like the classic fast event callback.
/// </summary>
private sealed class NotificationHandler : V2.ISubscriptionNotificationHandler
{
public NotificationHandler(EventWorkload owner, SubscriptionSetup setup)
{
m_owner = owner;
m_setup = setup;
}
public ValueTask OnDataChangeNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
ReadOnlyMemory<V2.DataValueChange> notification,
V2.PublishState publishStateMask,
IReadOnlyList<string> stringTable)
{
return ValueTask.CompletedTask;
}
public ValueTask OnEventDataNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
ReadOnlyMemory<V2.EventNotification> notification,
V2.PublishState publishStateMask,
IReadOnlyList<string> stringTable)
{
DateTime now = DateTime.UtcNow;
int count = 0;
foreach (V2.EventNotification e in notification.Span)
{
count++;
m_owner.RecordLatency(now, count, e.Fields);
}
Interlocked.Add(ref m_owner.m_events, count);
return ValueTask.CompletedTask;
}
public ValueTask OnKeepAliveNotificationAsync(
V2.ISubscription subscription,
uint sequenceNumber,
DateTime publishTime,
V2.PublishState publishStateMask)
{
return ValueTask.CompletedTask;
}
public ValueTask OnSubscriptionStateChangedAsync(
V2.ISubscription subscription,
V2.SubscriptionState state,
V2.PublishState publishStateMask,
CancellationToken ct = default)
{
m_setup.OnStateChanged(state);
return ValueTask.CompletedTask;
}
private readonly EventWorkload m_owner;
private readonly SubscriptionSetup m_setup;
}
private readonly ISession[] m_sessions;
private readonly int m_subscriptions;
private readonly int m_publishingInterval;
+344
View File
@@ -0,0 +1,344 @@
/* ========================================================================
* Copyright (c) 2005-2025 The OPC Foundation, Inc. All rights reserved.
*
* OPC Foundation MIT License 1.00
*
* Permission is hereby granted, free of charge, to any person
* obtaining a copy of this software and associated documentation
* files (the "Software"), to deal in the Software without
* restriction, including without limitation the rights to use,
* copy, modify, merge, publish, distribute, sublicense, and/or sell
* copies of the Software, and to permit persons to whom the
* Software is furnished to do so, subject to the following
* conditions:
*
* The above copyright notice and this permission notice shall be
* included in all copies or substantial portions of the Software.
* THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND,
* EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES
* OF MERCHANTABILITY, FITNESS FOR A PARTICULAR PURPOSE AND
* NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR COPYRIGHT
* HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY,
* WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING
* FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR
* OTHER DEALINGS IN THE SOFTWARE.
*
* The complete license agreement can be found here:
* http://opcfoundation.org/License/MIT/1.00/
* ======================================================================*/
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Globalization;
using System.Linq;
using System.Runtime;
using System.Threading;
using System.Threading.Tasks;
namespace Opc.Ua.Perf.ServerLoadHarness
{
/// <summary>
/// Listens to the garbage collection events of its own process (runtime provider, GC
/// keyword, informational level: a handful of events per collection, no allocation
/// sampling) and summarizes a measurement window: collections by generation and
/// trigger, pause and suspension percentiles, bytes promoted per gen0/gen1
/// collection, the heap count DATAS chose and the gen0 budget.
/// </summary>
/// <remarks>
/// Collections and pauses are tracked separately. A background gen2 overlaps foreground
/// gen0/gen1 collections and stops the threads more than once, so a collection is
/// identified by its count from start to end (its heap statistics follow its end), and
/// every suspend/restart interval is a pause of its own.
/// </remarks>
internal sealed class GcListener : EventListener
{
/// <summary>
/// Starts recording the window; earlier collections are dropped.
/// </summary>
public void Mark()
{
lock (m_lock)
{
m_collections.Clear();
m_open.Clear();
m_pauses.Clear();
m_heaps.Clear();
m_budgets.Clear();
m_ended = null;
m_suspendStart = default;
m_suspendEnd = default;
// events are dispatched later: the induced collection before the mark is not part of the window
m_markTime = DateTime.UtcNow;
m_endTime = DateTime.MaxValue;
m_sawAfterEnd = false;
m_recording = true;
}
}
/// <summary>
/// Ends the window: events stamped after now are not counted, events stamped before
/// now still are when they arrive later.
/// </summary>
public void End()
{
lock (m_lock)
{
m_endTime = DateTime.UtcNow;
}
}
/// <summary>
/// Waits until the events of the window have been delivered and returns its summary line.
/// </summary>
/// <remarks>
/// Events arrive in order but later than they happen. A gen0 collection induced after
/// <see cref="End"/> produces events stamped after the window; once one arrives, every
/// event of the window has arrived too (or the wait gives up after two seconds).
/// </remarks>
public async Task<string> ReportAsync()
{
GC.Collect(0, GCCollectionMode.Forced, blocking: true);
var wait = Stopwatch.StartNew();
while (!Volatile.Read(ref m_sawAfterEnd) && wait.ElapsedMilliseconds < 2000)
{
await Task.Delay(10).ConfigureAwait(false);
}
return Report();
}
private string Report()
{
List<Collection> all;
List<Pause> pauses;
List<long> heaps;
List<long> budgets;
lock (m_lock)
{
m_recording = false;
all = [.. m_collections];
pauses = [.. m_pauses];
heaps = [.. m_heaps];
budgets = [.. m_budgets];
}
var text = new System.Text.StringBuilder();
text.Append(CultureInfo.InvariantCulture,
$"mode={(GCSettings.IsServerGC ? "server" : "workstation")}{(GCSettings.LatencyMode == GCLatencyMode.Batch ? string.Empty : "+concurrent")} n={all.Count}");
foreach (IGrouping<string, Collection> g in all
.GroupBy(c => FormattableString.Invariant($"gen{c.Depth}{(c.Type == 1 ? "bg" : string.Empty)}/{ReasonName(c.Reason)}"))
.OrderByDescending(g => g.Count()))
{
text.Append(CultureInfo.InvariantCulture, $" {g.Key}={g.Count()}");
}
if (pauses.Count > 0)
{
double[] pauseMs = [.. pauses.Select(p => p.PauseMs).Order()];
double[] suspendMs = [.. pauses.Select(p => p.SuspendMs).Order()];
text.Append(CultureInfo.InvariantCulture,
$" pauses={pauseMs.Length} p50={Pct(pauseMs, 0.5):F2} p99={Pct(pauseMs, 0.99):F2} max={pauseMs[^1]:F2} sum={pauseMs.Sum():F0}ms");
text.Append(CultureInfo.InvariantCulture,
$" suspend p99={Pct(suspendMs, 0.99):F2} max={suspendMs[^1]:F2}ms");
}
List<Collection> ended = all.Where(c => c.HasStats).ToList();
if (ended.Count > 0)
{
AppendPromoted(text, ended, 0);
AppendPromoted(text, ended, 1);
double pinned = ended.Average(c => (double)c.Pinned);
text.Append(CultureInfo.InvariantCulture, $" pinned~{pinned:F0}");
// the generation sizes after the collection that ended last
Collection last = ended.MaxBy(c => c.EndOrder)!;
text.Append(CultureInfo.InvariantCulture,
$" gen2MB={last.Gen2Size / 1048576.0:F1} lohMB={last.LohSize / 1048576.0:F1}");
// the largest heap left after a collection in the window
text.Append(CultureInfo.InvariantCulture,
$" peakAfterGcMB={ended.Max(c => c.HeapSize) / 1048576.0:F1}");
}
GCMemoryInfo info = GC.GetGCMemoryInfo();
text.Append(CultureInfo.InvariantCulture,
$" committedMB={info.TotalCommittedBytes / 1048576.0:F1} limitMB={info.TotalAvailableMemoryBytes / 1048576}");
if (heaps.Count > 0)
{
text.Append(CultureInfo.InvariantCulture, $" heaps={heaps.Min()}..{heaps.Max()}");
}
if (budgets.Count > 0)
{
text.Append(CultureInfo.InvariantCulture,
$" gen0budgetMB~{budgets.Average() / 1048576.0:F1}");
}
return text.ToString();
}
/// <inheritdoc/>
protected override void OnEventSourceCreated(EventSource eventSource)
{
if (eventSource.Name == "Microsoft-Windows-DotNETRuntime")
{
// GC keyword
EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)0x1);
}
}
/// <inheritdoc/>
protected override void OnEventWritten(EventWrittenEventArgs e)
{
string? name = e.EventName;
if (name == null || e.Payload == null)
{
return;
}
lock (m_lock)
{
DateTime stamp = e.TimeStamp.ToUniversalTime();
if (!m_recording || stamp < m_markTime)
{
return;
}
if (stamp > m_endTime)
{
// the delivery boundary of ReportAsync
m_sawAfterEnd = true;
return;
}
if (name.StartsWith("GCSuspendEEBegin", StringComparison.Ordinal))
{
m_suspendStart = e.TimeStamp;
m_suspendEnd = default;
}
else if (name.StartsWith("GCSuspendEEEnd", StringComparison.Ordinal))
{
m_suspendEnd = e.TimeStamp;
}
else if (name.StartsWith("GCRestartEEEnd", StringComparison.Ordinal))
{
// every stop-the-world interval, including the extra ones of a background gen2
if (m_suspendStart != default)
{
m_pauses.Add(new Pause(
(e.TimeStamp - m_suspendStart).TotalMilliseconds,
m_suspendEnd < m_suspendStart ? 0 : (m_suspendEnd - m_suspendStart).TotalMilliseconds));
}
m_suspendStart = default;
}
else if (name.StartsWith("GCStart", StringComparison.Ordinal))
{
var collection = new Collection
{
Depth = ToInt(e, "Depth"),
Reason = ToInt(e, "Reason"),
Type = ToInt(e, "Type")
};
m_collections.Add(collection);
m_open[ToLong(e, "Count")] = collection;
}
else if (name.StartsWith("GCEnd", StringComparison.Ordinal))
{
// the heap statistics that follow describe the collection that ended
m_ended = m_open.Remove(ToLong(e, "Count"), out Collection? collection) ? collection : null;
}
else if (name.StartsWith("GCHeapStats", StringComparison.Ordinal) && m_ended != null)
{
Collection c = m_ended;
c.HasStats = true;
c.EndOrder = ++m_endOrder;
c.Promoted0 = ToLong(e, "TotalPromotedSize0");
c.Promoted1 = ToLong(e, "TotalPromotedSize1");
c.Gen2Size = ToLong(e, "GenerationSize2");
c.LohSize = ToLong(e, "GenerationSize3");
c.Pinned = ToLong(e, "PinnedObjectCount");
c.HeapSize = ToLong(e, "GenerationSize0") + ToLong(e, "GenerationSize1") +
c.Gen2Size + c.LohSize + ToLong(e, "GenerationSize4");
m_ended = null;
}
else if (name.StartsWith("GCGlobalHeapHistory", StringComparison.Ordinal))
{
m_heaps.Add(ToLong(e, "NumHeaps"));
m_budgets.Add(ToLong(e, "FinalYoungestDesired"));
}
}
}
private static void AppendPromoted(System.Text.StringBuilder text, List<Collection> all, int depth)
{
// every collection condemns gen0; gen1 is condemned by gen1 and gen2 collections
List<Collection> gens = all.Where(c => c.Depth >= depth).ToList();
if (gens.Count == 0)
{
return;
}
// the bytes that survived the generation (gen0 into gen1, gen1 into gen2)
double promoted = gens.Average(c => (double)(depth == 0 ? c.Promoted0 : c.Promoted1));
text.Append(CultureInfo.InvariantCulture, $" survivedKB/gen{depth}={promoted / 1024:F0}");
}
private static double Pct(double[] sorted, double q)
{
return sorted[Math.Min(sorted.Length - 1, (int)(q * sorted.Length))];
}
private static string ReasonName(int reason)
{
return reason switch
{
0 => "alloc",
1 => "induced",
2 => "lowmem",
3 => "empty",
4 => "loh",
5 => "oosSoh",
6 => "oosLoh",
7 => "inducedNotForced",
8 => "stress",
9 => "lowmemHost",
_ => reason.ToString(CultureInfo.InvariantCulture)
};
}
private static int ToInt(EventWrittenEventArgs e, string name)
{
return (int)ToLong(e, name);
}
private static long ToLong(EventWrittenEventArgs e, string name)
{
int index = e.PayloadNames?.IndexOf(name) ?? -1;
return index < 0 || e.Payload![index] == null
? 0
: Convert.ToInt64(e.Payload[index], CultureInfo.InvariantCulture);
}
private sealed class Collection
{
public int Depth;
public int Reason;
public int Type;
public bool HasStats;
public long EndOrder;
public long Promoted0;
public long Promoted1;
public long Gen2Size;
public long LohSize;
public long Pinned;
public long HeapSize;
}
private readonly record struct Pause(double PauseMs, double SuspendMs);
private readonly object m_lock = new();
private readonly List<Collection> m_collections = [];
private readonly Dictionary<long, Collection> m_open = [];
private readonly List<Pause> m_pauses = [];
private readonly List<long> m_heaps = [];
private readonly List<long> m_budgets = [];
private Collection? m_ended;
private long m_endOrder;
private DateTime m_suspendStart;
private DateTime m_suspendEnd;
private DateTime m_markTime;
private DateTime m_endTime = DateTime.MaxValue;
private bool m_sawAfterEnd;
private bool m_recording;
}
}
+220 -16
View File
@@ -36,7 +36,7 @@
// [--duration S] [--warmup S] [--security none|sign|encrypt] [--diag 0|1] [--audit 0|1]
// [--subs S] [--pub ms] [--write-interval ms] [--write-nodes K]
// [--trace file] [--trace-profile p] [--out file]
// [--client classic|managed] [--callback fast|item] [--trace-side server|client]
// [--client managed|classic|shared] [--callback fast|item] [--trace-side server|client]
// Spawns the server child, drives the load and prints a report of client latency
// and the CPU / GC / allocation deltas of both processes for the measurement window.
@@ -48,6 +48,7 @@ using System.Diagnostics;
using System.Globalization;
using System.IO;
using System.Linq;
using System.Numerics;
using System.Runtime.CompilerServices;
using System.Text;
using System.Threading;
@@ -69,6 +70,14 @@ namespace Opc.Ua.Perf.ServerLoadHarness
{
private static readonly Dictionary<string, string> s_args = new(StringComparer.OrdinalIgnoreCase);
// client GC events of the window (--gc-events 0 turns the listener off)
private static GcListener? s_gcListener;
// processor masks of a constrained client run (--client-cores), set by RunConstrainedAsync
private const string kClientAffinityVariable = "PERF_CLIENT_AFFINITY";
private const string kServerAffinityVariable = "PERF_SERVER_AFFINITY";
private const string kConstrainedVariable = "PERF_CONSTRAINED";
/// <summary>
/// Runs the server or the load driver.
/// </summary>
@@ -92,11 +101,90 @@ namespace Opc.Ua.Perf.ServerLoadHarness
{
return await RunServerAsync().ConfigureAwait(false);
}
if ((s_args.ContainsKey("client-cores") || s_args.ContainsKey("client-memory")) &&
NativeWorkerBenchmark.IsScenario(Arg("scenario", "read")))
{
// the native workers are not .NET processes; they use --client-affinity
Console.WriteLine(
"--client-cores and --client-memory apply to the .NET client scenarios; " +
"use --client-affinity and --server-affinity with the native workers.");
return 2;
}
if ((s_args.ContainsKey("client-cores") || s_args.ContainsKey("client-memory")) &&
Environment.GetEnvironmentVariable(kConstrainedVariable) == null)
{
return await RunConstrainedAsync(args).ConfigureAwait(false);
}
return NativeWorkerBenchmark.IsScenario(Arg("scenario", "read"))
? await NativeWorkerBenchmark.RunAsync(args).ConfigureAwait(false)
: await RunDriverAsync(args).ConfigureAwait(false);
}
/// <summary>
/// Runs the harness again as a client confined like a container: <c>--client-cores N</c>
/// gives it the last N of the processors this process may use (the runtime sizes the
/// thread pool and GC for N through <c>DOTNET_PROCESSOR_COUNT</c>) and the server the
/// others; <c>--client-memory MB</c> sets the GC heap hard limit to 75 % of MB, the limit
/// .NET derives from a container memory limit.
/// </summary>
/// <remarks>
/// Processor confinement uses the process affinity mask, which on Windows applies to all
/// threads of a process. On Linux it applies only to the main thread, so there the
/// client belongs in a cgroup (for example <c>docker --cpuset-cpus</c>) or under
/// <c>taskset</c> instead.
/// </remarks>
private static async Task<int> RunConstrainedAsync(string[] args)
{
var startInfo = new ProcessStartInfo(Environment.ProcessPath!) { UseShellExecute = false };
foreach (string arg in args)
{
startInfo.ArgumentList.Add(arg);
}
startInfo.Environment[kConstrainedVariable] = "1";
if (TryGetArg("client-cores", out string? coresArg))
{
if (!OperatingSystem.IsWindows())
{
Console.WriteLine(
"--client-cores is supported on Windows only, where the affinity mask applies to all threads; " +
"on Linux run the client in a cgroup (docker --cpuset-cpus) or under taskset.");
return 2;
}
// the processors this process may use, which can be a subset of the machine,
// within the processor group of the process (at most 64)
using Process self = Process.GetCurrentProcess();
long allowed = self.ProcessorAffinity;
var processors = new List<int>();
for (int bit = 0; bit < 64; bit++)
{
if ((allowed & (1L << bit)) != 0)
{
processors.Add(bit);
}
}
int cores = Math.Clamp(int.Parse(coresArg!, CultureInfo.InvariantCulture), 1, processors.Count);
long clientMask = 0;
foreach (int bit in processors.Skip(processors.Count - cores))
{
clientMask |= 1L << bit;
}
startInfo.Environment[kClientAffinityVariable] = clientMask.ToString("X", CultureInfo.InvariantCulture);
startInfo.Environment["DOTNET_PROCESSOR_COUNT"] = cores.ToString(CultureInfo.InvariantCulture);
if (cores < processors.Count)
{
startInfo.Environment[kServerAffinityVariable] =
(allowed & ~clientMask).ToString("X", CultureInfo.InvariantCulture);
}
}
if (TryGetArg("client-memory", out string? memory))
{
long limit = long.Parse(memory!, CultureInfo.InvariantCulture) * 1048576 * 3 / 4;
startInfo.Environment["DOTNET_GCHeapHardLimit"] = "0x" + limit.ToString("X", CultureInfo.InvariantCulture);
}
using Process child = Process.Start(startInfo)!;
await child.WaitForExitAsync().ConfigureAwait(false);
return child.ExitCode;
}
internal static bool TryGetArg(string name, out string? value)
{
return s_args.TryGetValue(name, out value);
@@ -285,12 +373,46 @@ namespace Opc.Ua.Perf.ServerLoadHarness
int warmupSeconds = ArgInt("warmup", 10);
int port = ArgInt("port", 62555 + (Environment.ProcessId % 1000));
string security = Arg("security", "none");
if (ArgInt("gc-events", 1) != 0)
{
s_gcListener = new GcListener();
}
// a constrained client starts the server before it confines itself, so the server
// does not inherit the client's processors; the server runtime is sized for the
// processors it keeps (SERVER_DOTNET_PROCESSOR_COUNT still overrides)
string? clientAffinity = Environment.GetEnvironmentVariable(kClientAffinityVariable);
string? serverAffinity = Environment.GetEnvironmentVariable(kServerAffinityVariable);
Dictionary<string, string>? serverEnvironment = serverAffinity == null
? null
: new Dictionary<string, string>(StringComparer.Ordinal)
{
["DOTNET_PROCESSOR_COUNT"] = BitOperations.PopCount(Convert.ToUInt64(serverAffinity, 16))
.ToString(CultureInfo.InvariantCulture)
};
(Process startedServer, BlockingCollection<string> startedLines) = StartServerChild(
FormattableString.Invariant(
$"server --port {port} --diag {Arg("diag", "0")} --audit {Arg("audit", "0")} --threads {Arg("threads", "200")} --counters {(scenario == "counters" ? Arg("nodes", "1") : "0")} --sampling {Arg("sampling", "10")} --queue {Arg("queue", "2000")}"));
$"server --port {port} --diag {Arg("diag", "0")} --audit {Arg("audit", "0")} --threads {Arg("threads", "200")} --counters {(scenario == "counters" ? Arg("nodes", "1") : "0")} --sampling {Arg("sampling", "10")} --queue {Arg("queue", "2000")}"),
serverEnvironment);
using Process server = startedServer;
using BlockingCollection<string> serverLines = startedLines;
if (serverAffinity != null && OperatingSystem.IsWindows())
{
// the server keeps the processors the constrained client does not have
server.ProcessorAffinity = (nint)Convert.ToInt64(serverAffinity, 16);
}
if (clientAffinity != null && OperatingSystem.IsWindows())
{
// the process mask applies to the threads the runtime has already started, too
using Process self = Process.GetCurrentProcess();
self.ProcessorAffinity = (nint)Convert.ToInt64(clientAffinity, 16);
}
if (Environment.GetEnvironmentVariable(kConstrainedVariable) != null)
{
Console.WriteLine(FormattableString.Invariant(
$"constrained client: processors={Environment.ProcessorCount} mask=0x{clientAffinity ?? "all"} ") +
FormattableString.Invariant(
$"server mask=0x{serverAffinity ?? "all"} heapLimitMB={GC.GetGCMemoryInfo().TotalAvailableMemoryBytes / 1048576}"));
}
string ready = serverLines.Take();
if (!ready.StartsWith("READY", StringComparison.Ordinal))
{
@@ -325,10 +447,10 @@ namespace Opc.Ua.Perf.ServerLoadHarness
}
}
// managed (default): ManagedSession with the default V2 subscription engine.
// classic: Session from the default session factory (classic subscription engine).
// managed: ManagedSession with the default V2 subscription engine.
// shared: classic Sessions whose secure channels come from one ClientChannelManager.
string clientKind = Arg("client", "classic");
string clientKind = Arg("client", "managed");
ConfiguredEndpoint? endpointForBuilder = clientKind is "managed" or "shared"
? await client.GetEndpointAsync(new Uri(url), policy, selected).ConfigureAwait(false)
: null;
@@ -350,6 +472,7 @@ namespace Opc.Ua.Perf.ServerLoadHarness
"managed" => await new ManagedSessionBuilder(client.Config, telemetry)
.UseEndpoint(endpointForBuilder!)
.WithSessionTimeout(TimeSpan.FromSeconds(60))
.WithPoolNotifications(ArgInt("pool-notifications", 0) != 0)
.ConnectAsync(ct)
.ConfigureAwait(false),
"shared" => await Session.CreateAsync(
@@ -420,12 +543,15 @@ namespace Opc.Ua.Perf.ServerLoadHarness
Take(serverLines, "MARKED");
GC.Collect();
GC.WaitForPendingFinalizers();
s_gcListener?.Mark();
ProcessStats clientMark = ProcessStats.Capture();
workload.ResetStats();
var window = Stopwatch.StartNew();
TimeSpan clientCpuStart = Process.GetCurrentProcess().TotalProcessorTime;
await Task.Delay(TimeSpan.FromSeconds(durationSeconds)).ConfigureAwait(false);
string clientProcess = ProcessStats.Capture().Delta(clientMark);
// the window ends here; GC events stamped before this arrive later and still count
s_gcListener?.End();
await server.StandardInput.WriteLineAsync("report").ConfigureAwait(false);
string report = Take(serverLines, "REPORT")[7..];
// freeze the client counts at the end of the server window
@@ -456,6 +582,7 @@ namespace Opc.Ua.Perf.ServerLoadHarness
Console.WriteLine("trace: " + trace);
}
string? clientGc = s_gcListener == null ? null : await s_gcListener.ReportAsync().ConfigureAwait(false);
var result = new StringBuilder();
result.Append(CultureInfo.InvariantCulture, $"RESULT scenario={scenario} security={security} sessions={sessionCount} ")
.Append(string.Join(' ', args.Skip(1)))
@@ -463,6 +590,10 @@ namespace Opc.Ua.Perf.ServerLoadHarness
.Append(" client: ").Append(clientReport).Append('\n')
.Append(" server: ").Append(report).Append('\n')
.Append(" client-process: ").Append(clientProcess).Append('\n');
if (clientGc != null)
{
result.Append(" client-gc: ").Append(clientGc).Append('\n');
}
(double serverMb, double serverCpuMs) = ParseProcessReport(report);
if (operations > 0)
{
@@ -522,6 +653,19 @@ namespace Opc.Ua.Perf.ServerLoadHarness
RedirectStandardOutput = true,
UseShellExecute = false
};
// GC and processor settings of the harness configure the measured client; the server
// inherits the environment, so they are removed and only SERVER_ variables configure it
foreach (string name in startInfo.Environment.Keys.ToList())
{
if (name.StartsWith("DOTNET_GC", StringComparison.OrdinalIgnoreCase) ||
name.StartsWith("COMPlus_GC", StringComparison.OrdinalIgnoreCase) ||
name.StartsWith("DOTNET_ThreadPool_", StringComparison.OrdinalIgnoreCase) ||
name.Equals("DOTNET_PROCESSOR_COUNT", StringComparison.OrdinalIgnoreCase) ||
name.StartsWith("PERF_", StringComparison.Ordinal))
{
startInfo.Environment.Remove(name);
}
}
if (defaultEnvironment != null)
{
foreach (KeyValuePair<string, string> variable in defaultEnvironment)
@@ -663,39 +807,99 @@ namespace Opc.Ua.Perf.ServerLoadHarness
}
/// <summary>
/// Latency samples (Stopwatch ticks) recorded by many threads. ConcurrentBag keeps a
/// list per thread, so recording does not contend between the load threads.
/// Latency histogram (Stopwatch ticks) recorded by many threads without allocating:
/// log-linear buckets with 64 steps per power of two (at most ~1.6 % error), so the
/// recorder does not add allocations, promotions or large arrays to the measured client.
/// </summary>
internal sealed class LatencyRecorder
{
public void Record(long ticks)
{
m_samples.Add(ticks);
if (ticks < 0)
{
ticks = 0;
}
Interlocked.Increment(ref m_buckets[Index(ticks)]);
long max = Volatile.Read(ref m_max);
while (ticks > max)
{
long seen = Interlocked.CompareExchange(ref m_max, ticks, max);
if (seen == max)
{
break;
}
max = seen;
}
}
public void Clear()
{
m_samples.Clear();
for (int i = 0; i < m_buckets.Length; i++)
{
Interlocked.Exchange(ref m_buckets[i], 0);
}
Interlocked.Exchange(ref m_max, 0);
}
public string Percentiles()
{
var all = new List<long>(m_samples);
if (all.Count == 0)
long[] counts = new long[m_buckets.Length];
long total = 0;
for (int i = 0; i < counts.Length; i++)
{
counts[i] = Volatile.Read(ref m_buckets[i]);
total += counts[i];
}
if (total == 0)
{
return "n=0";
}
all.Sort();
double Ms(double quantile)
{
return all[Math.Min(all.Count - 1, (int)(quantile * all.Count))] * 1000.0 / Stopwatch.Frequency;
long rank = Math.Min(total - 1, (long)(quantile * total));
long seen = 0;
for (int i = 0; i < counts.Length; i++)
{
seen += counts[i];
if (seen > rank)
{
return Value(i) * 1000.0 / Stopwatch.Frequency;
}
}
return Volatile.Read(ref m_max) * 1000.0 / Stopwatch.Frequency;
}
return FormattableString.Invariant(
$"n={all.Count} p50={Ms(0.5):F3}ms p90={Ms(0.9):F3}ms p99={Ms(0.99):F3}ms ") +
FormattableString.Invariant($"p999={Ms(0.999):F3}ms max={Ms(1):F3}ms");
$"n={total} p50={Ms(0.5):F3}ms p90={Ms(0.9):F3}ms p99={Ms(0.99):F3}ms ") +
FormattableString.Invariant(
$"p999={Ms(0.999):F3}ms max={Volatile.Read(ref m_max) * 1000.0 / Stopwatch.Frequency:F3}ms");
}
private readonly ConcurrentBag<long> m_samples = [];
private static int Index(long ticks)
{
if (ticks < 2 * kSteps)
{
return (int)ticks;
}
int shift = 63 - BitOperations.LeadingZeroCount((ulong)ticks) - kBits;
return (2 * kSteps) + ((shift - 1) * kSteps) + (int)((ticks >> shift) - kSteps);
}
private static double Value(int index)
{
if (index < 2 * kSteps)
{
return index;
}
int shift = ((index - (2 * kSteps)) / kSteps) + 1;
long mantissa = ((index - (2 * kSteps)) % kSteps) + kSteps;
// bucket midpoint
return (mantissa << shift) + ((1L << shift) / 2.0);
}
private const int kBits = 6;
private const int kSteps = 1 << kBits;
private readonly long[] m_buckets = new long[(2 * kSteps) + (64 * kSteps)];
private long m_max;
}
/// <summary>
+128
View File
@@ -37,6 +37,7 @@ using System;
using System.Collections.Generic;
using System.Globalization;
using System.Linq;
using System.Text;
using Microsoft.Diagnostics.Tracing;
using Microsoft.Diagnostics.Tracing.Etlx;
using Microsoft.Diagnostics.Tracing.Parsers.Clr;
@@ -241,20 +242,86 @@ namespace Opc.Ua.Perf.TraceAnalyzer
private static void Collections(TraceLog log)
{
var counts = new Dictionary<string, int>(StringComparer.Ordinal);
var reasons = new Dictionary<string, int>(StringComparer.Ordinal);
var pauses = new List<double>();
var suspensions = new List<double>();
// time and bytes of the phases of a blocking collection that does not overlap a
// background gen2: marking per heap (each heap's time since its previous mark event,
// summed over heaps), plan to end and end to restart as elapsed time
var phaseMs = new Dictionary<string, double>(StringComparer.Ordinal);
var markedBytes = new Dictionary<string, double>(StringComparer.Ordinal);
var heapLastMark = new Dictionary<int, double>();
double suspendStart = 0;
double collectionStart = 0;
double collectionEnd = 0;
long phasedCount = -1;
long backgroundCount = -1;
int phased = 0;
int unphased = 0;
foreach (TraceEvent e in log.Events)
{
if (e is GCStartTraceData start)
{
string key = FormattableString.Invariant($"gen{start.Depth} {start.Type} {start.Reason}");
counts[key] = counts.TryGetValue(key, out int n) ? n + 1 : 1;
if (start.Type == GCType.BackgroundGC || backgroundCount >= 0)
{
// a background gen2, or a foreground collection inside one
if (start.Type == GCType.BackgroundGC)
{
backgroundCount = start.Count;
}
phasedCount = -1;
unphased++;
continue;
}
if (suspendStart > 0)
{
Add(phaseMs, "0 suspend+start", e.TimeStampRelativeMSec - suspendStart);
}
phasedCount = start.Count;
collectionStart = e.TimeStampRelativeMSec;
collectionEnd = 0;
heapLastMark.Clear();
phased++;
}
else if (e.EventName == "GC/MarkWithType" && phasedCount >= 0 && collectionEnd == 0)
{
int type = Convert.ToInt32(e.PayloadByName("Type") ?? -1, CultureInfo.InvariantCulture);
int heap = Convert.ToInt32(e.PayloadByName("HeapNum") ?? 0, CultureInfo.InvariantCulture);
string name = "1 mark " + (type is >= 0 and < 10 ? s_markTypes[type] : type.ToString(CultureInfo.InvariantCulture));
double previous = heapLastMark.TryGetValue(heap, out double last) ? last : collectionStart;
Add(phaseMs, name, e.TimeStampRelativeMSec - previous);
Add(markedBytes, name, Convert.ToDouble(e.PayloadByName("Promoted") ?? 0, CultureInfo.InvariantCulture));
heapLastMark[heap] = e.TimeStampRelativeMSec;
}
else if (e is GCEndTraceData end)
{
if (end.Count == backgroundCount)
{
backgroundCount = -1;
}
else if (end.Count == phasedCount)
{
// plan, relocate, compact or sweep after the last heap finished marking
double lastMark = heapLastMark.Count > 0 ? heapLastMark.Values.Max() : collectionStart;
Add(phaseMs, "2 plan+relocate+compact", e.TimeStampRelativeMSec - lastMark);
collectionEnd = e.TimeStampRelativeMSec;
}
}
else if (e is GCSuspendEETraceData)
{
suspendStart = e.TimeStampRelativeMSec;
}
else if (e.EventName == "GC/PerHeapHistory" && e.PayloadByName("CondemnReasons0") is object r0)
{
// why the generation was condemned: the generation each tuning input asked for,
// and the conditions that raised it (gc_condemn_reason_gen / _condition)
string key = "condemn " + CondemnReasons(
Convert.ToInt64(r0, CultureInfo.InvariantCulture),
Convert.ToInt64(e.PayloadByName("CondemnReasons1") ?? 0, CultureInfo.InvariantCulture));
reasons[key] = reasons.TryGetValue(key, out int n) ? n + 1 : 1;
}
else if (e.EventName == "GC/SuspendEEStop" && suspendStart > 0)
{
// time to bring every managed thread to a safe point
@@ -263,6 +330,11 @@ namespace Opc.Ua.Perf.TraceAnalyzer
else if (e.EventName == "GC/RestartEEStop" && suspendStart > 0)
{
pauses.Add(e.TimeStampRelativeMSec - suspendStart);
if (phasedCount >= 0 && collectionEnd > 0)
{
Add(phaseMs, "3 end+restart", e.TimeStampRelativeMSec - collectionEnd);
phasedCount = -1;
}
suspendStart = 0;
}
}
@@ -272,6 +344,22 @@ namespace Opc.Ua.Perf.TraceAnalyzer
{
Console.WriteLine(FormattableString.Invariant($" {entry.Value,7} {entry.Key}"));
}
foreach (KeyValuePair<string, int> entry in reasons.OrderByDescending(c => c.Value))
{
Console.WriteLine(FormattableString.Invariant($" {entry.Value,7} {entry.Key}"));
}
if (phased > 0)
{
Console.WriteLine(FormattableString.Invariant(
$"phases (average per blocking collection outside background GCs, {phased} of {phased + unphased}; mark phases summed over heaps):"));
foreach (KeyValuePair<string, double> entry in phaseMs.OrderBy(c => c.Key, StringComparer.Ordinal))
{
string bytes = markedBytes.TryGetValue(entry.Key, out double b)
? FormattableString.Invariant($" {b / phased / 1024,9:F1} KB marked")
: string.Empty;
Console.WriteLine(FormattableString.Invariant($" {entry.Value / phased,8:F3} ms {entry.Key}{bytes}"));
}
}
if (suspensions.Count > 0)
{
suspensions.Sort();
@@ -290,6 +378,46 @@ namespace Opc.Ua.Perf.TraceAnalyzer
}
}
private static readonly string[] s_markTypes =
[
"stack", "finalizeQueue", "handles", "older(cards)", "sizedRef", "overflow",
"dependentHandles", "newFinalizeQueue", "steal", "bgcRoots"
];
/// <summary>
/// Decodes the condemn reasons of a GCPerHeapHistory event: CondemnReasons0 packs the
/// generation each input asked for in 2-bit fields (initial, final per heap, allocation
/// budget, time tuning, ...), CondemnReasons1 is a set of condition flags.
/// </summary>
private static string CondemnReasons(long gens, long conditions)
{
string[] genNames = ["initial", "perHeap", "budget", "timeTuning"];
string[] flagNames =
[
"inducedFull", "expandFull", "highMem", "veryHighMem", "lowEphemeral", "lowCard",
"ephHighFrag", "maxHighFrag", "maxHighFragE", "maxHighFragM", "maxHighFragVm",
"maxGen1", "beforeOom", "gen2TooSmall", "inducedNoForce", "beforeBgc",
"almostMaxAlloc"
];
var text = new StringBuilder();
for (int i = 0; i < genNames.Length; i++)
{
long gen = (gens >> (2 * i)) & 3;
if (gen != 0)
{
text.Append(CultureInfo.InvariantCulture, $"{genNames[i]}=gen{gen} ");
}
}
for (int i = 0; i < 32; i++)
{
if ((conditions & (1L << i)) != 0)
{
text.Append('+').Append(i < flagNames.Length ? flagNames[i] : "c" + i.ToString(CultureInfo.InvariantCulture)).Append(' ');
}
}
return text.Length == 0 ? "gen0" : text.ToString().TrimEnd();
}
/// <summary>
/// Event counts (including the heap counts DATAS chose and the GC handle kinds), and for
/// each suspension longer than <paramref name="thresholdMs"/> the events recorded between
+3 -3
View File
@@ -4,9 +4,9 @@
--scenario browse
--scenario read --nodes 1 --security encrypt
--scenario read --nodes 100 --security encrypt
--scenario read --nodes 1 --client managed
--scenario read --nodes 1 --sessions 200
--scenario sub --subs 5 --nodes 100 --pub 100 --write-interval 50
--scenario sub --subs 5 --nodes 100 --pub 100 --write-interval 50 --callback item
--scenario sub --subs 5 --nodes 100 --pub 100 --write-interval 50 --client managed
--scenario sub --subs 5 --nodes 100 --pub 100 --write-interval 50 --pool-notifications 1
--scenario sub --subs 5 --nodes 100 --pub 100 --write-interval 50 --security encrypt
--scenario events --sessions 5
--scenario events --sessions 5 --pool-notifications 1
@@ -857,8 +857,8 @@ namespace Opc.Ua.Core.Tests.Stack.Transport
await CompletesWithinAsync(requestTask, 30).ConfigureAwait(false),
Is.True,
"the request did not time out");
ServiceResultException requestError = Assert.ThrowsAsync<ServiceResultException>(
async () => await requestTask.ConfigureAwait(false))!;
ServiceResultException requestError = (await Assert.ThrowsAsync<ServiceResultException>(
async () => await requestTask.ConfigureAwait(false)))!;
Assert.That(requestError.StatusCode, Is.EqualTo((uint)StatusCodes.BadRequestTimeout));
Assert.That(connectTask.IsCompleted, Is.False);
@@ -870,8 +870,8 @@ namespace Opc.Ua.Core.Tests.Stack.Transport
await CompletesWithinAsync(connectTask, 30).ConfigureAwait(false),
Is.True,
"the connect did not time out");
ServiceResultException connectError = Assert.ThrowsAsync<ServiceResultException>(
async () => await connectTask.ConfigureAwait(false))!;
ServiceResultException connectError = (await Assert.ThrowsAsync<ServiceResultException>(
async () => await connectTask.ConfigureAwait(false)))!;
Assert.That(connectError.StatusCode, Is.EqualTo((uint)StatusCodes.BadRequestTimeout));
}