GithubStar/UA-.NETStandard
1
0
Fork 0
mirror of https://github.com/OPCFoundation/UA-.NETStandard.git synced 2026-10-18 06:31:35 +08:00
Code Issues Packages Projects Releases Wiki Activity

Remove temporary RF1 refresh timing diagnostics

Browse Source
This commit is contained in:
Marc
2026-10-15 18:19:17 +02:00
parent d8f9fd843a
commit 6957dd465b
6 changed files with 6 additions and 652 deletions
Download Patch File Download Diff File Expand all files Collapse all files
src/Opc.Ua.WotCon.Client/WotRegistryClient.cs
+3 -24
View File
@@ -29,10 +29,8 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using Opc.Ua.Client;
using Opc.Ua.XRegistry;
using Opc.Ua.XRegistry.Client;
@@ -314,25 +312,9 @@ namespace Opc.Ua.WotCon.Client
new Variant(requestId)
]
};
CallResponse response;
long rfStart = Stopwatch.GetTimestamp(); // [DEBUG-G10-RF1]
bool rfCompleted = false; // [DEBUG-G10-RF1]
try
{
response = await Session
.CallAsync(new RequestHeader(), [request], ct)
.ConfigureAwait(false);
rfCompleted = true; // [DEBUG-G10-RF1]
}
finally
{
// [DEBUG-G10-RF1]
Telemetry.CreateLogger<WotRegistryClient>().ClientRefreshCall(
(Stopwatch.GetTimestamp() - rfStart) * 1000 / Stopwatch.Frequency,
Session.OperationTimeout,
Session.DefaultTimeoutHint,
rfCompleted);
}
CallResponse response = await Session
.CallAsync(new RequestHeader(), [request], ct)
.ConfigureAwait(false);
CallMethodResult callResult = GetFirstCallResult(response, "Refresh");
if (StatusCode.IsBad(callResult.StatusCode))
{
@@ -500,7 +482,6 @@ namespace Opc.Ua.WotCon.Client
WotRegistryDocument[] ordered = OrderThingModelsFirst(documents);
var outcomes = new WotRegistryDocumentLoadOutcome[ordered.Length];
var groups = new Dictionary<string, WotRegistryGroupClient>(StringComparer.Ordinal);
long rfUploadStart = Stopwatch.GetTimestamp(); // [DEBUG-G10-RF1]
for (int i = 0; i < ordered.Length; i++)
{
ct.ThrowIfCancellationRequested();
@@ -542,8 +523,6 @@ namespace Opc.Ua.WotCon.Client
}
WotRegistryRefreshResult? refreshResult = null;
Telemetry.CreateLogger<WotRegistryClient>().ClientUploadPhase( // [DEBUG-G10-RF1]
ordered.Length, (Stopwatch.GetTimestamp() - rfUploadStart) * 1000 / Stopwatch.Frequency);
if (refresh)
{
refreshResult = await RefreshAllAsync(
src/Opc.Ua.WotCon.Client/WotRegistryClientDiag.cs
-71
View File
@@ -1,71 +0,0 @@
/* ========================================================================
* Copyright (c) 2005-2026 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 Microsoft.Extensions.Logging;
namespace Opc.Ua
{
/// <summary>
/// [DEBUG-G10-RF1] Temporary event id offsets for the Opc.Ua.WotCon.Client assembly.
/// Remove together with every [DEBUG-G10-RF1] marker before the final repair.
/// </summary>
internal static class WotConClientEventIds
{
public const int WotRegistryClientDiag = 0;
}
}
namespace Opc.Ua.WotCon.Client
{
/// <summary>
/// [DEBUG-G10-RF1] Holds temporary source-generated client refresh timing log messages.
/// </summary>
internal static partial class WotRegistryClientDiagLog
{
/// <summary>
/// Logs the wall time of the document upload phase of a bulk load.
/// </summary>
[LoggerMessage(EventId = WotConClientEventIds.WotRegistryClientDiag + 0, Level = LogLevel.Warning,
Message = "[DEBUG-G10-RF1] client upload documents={Documents} uploadMs={UploadMs}")]
public static partial void ClientUploadPhase(this ILogger logger, int documents, long uploadMs);
/// <summary>
/// Logs the wall time and configured timeouts of one client Refresh call.
/// </summary>
[LoggerMessage(EventId = WotConClientEventIds.WotRegistryClientDiag + 1, Level = LogLevel.Warning,
Message = "[DEBUG-G10-RF1] client refresh callMs={CallMs} operationTimeoutMs={OperationTimeout} " +
"defaultTimeoutHintMs={TimeoutHint} completed={Completed}")]
public static partial void ClientRefreshCall(
this ILogger logger,
long callMs,
int operationTimeout,
int timeoutHint,
bool completed);
}
}
src/Opc.Ua.WotCon.Server/EventIds.cs
-1
View File
@@ -48,6 +48,5 @@ namespace Opc.Ua
public const int WotConnectivityNodeManager = 50;
public const int WotRegistryNodeManager = 60;
public const int WotProjectionViewNodeManager = 70;
public const int WotRefreshDiag = 80; // [DEBUG-G10-RF1]
}
}
src/Opc.Ua.WotCon.Server/Materialization/WotMaterializationCoordinator.cs
+3 -86
View File
@@ -114,13 +114,9 @@ namespace Opc.Ua.WotCon.Server.Materialization
throw new ObjectDisposedException(nameof(WotMaterializationCoordinator));
}
WotRefreshDiag? rfDiag = null; // [DEBUG-G10-RF1]
try
{
int rfKind = request.RequestId switch { "auto" => 1, "startup" => 2, _ => 0 }; // [DEBUG-G10-RF1]
rfDiag = new WotRefreshDiag(DiagLogger, m_mutex.CurrentCount, rfKind); // [DEBUG-G10-RF1]
await m_mutex.WaitAsync(cancellationToken).ConfigureAwait(false);
rfDiag.Acquired(); // [DEBUG-G10-RF1]
try
{
DateTime start = DateTime.UtcNow;
@@ -129,7 +125,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
if (request.ExpectedGeneration != 0 &&
request.ExpectedGeneration != m_generation)
{
rfDiag.Done(rejected: true); // [DEBUG-G10-RF1]
return RejectedResult(request, start);
}
@@ -151,7 +146,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
contentCache, version, token),
cancellationToken)
.ConfigureAwait(false);
rfDiag.Built(enabled.Count, closures.Length); // [DEBUG-G10-RF1]
var targetKeys = new HashSet<string>(
closures.Select(c => c.Key), StringComparer.Ordinal);
@@ -160,7 +154,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
(version, token) => ReadCachedContentAsync(contentCache, version, token),
m_converterOptions.MaxNodeCount);
declarationContext.AddAvailableNativePartitions(contentCache, m_converterOptions, cancellationToken);
rfDiag.Native(); // [DEBUG-G10-RF1]
uint newGeneration = m_generation + 1;
ImmutableArray<WoTResourceLoadResultDataType>.Builder results =
@@ -180,7 +173,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
retired += retiredCount;
skipped += retiredResults.Length;
results.AddRange(retiredResults);
rfDiag.Retired(); // [DEBUG-G10-RF1]
foreach (WotDependencyClosure closure in closures)
{
@@ -191,8 +183,7 @@ namespace Opc.Ua.WotCon.Server.Materialization
ClosureOutcome outcome = await ProcessClosureAsync(
snapshot, closure, newGeneration, force && inScope,
dryRun, strict, contentCache, declarationContext, rfDiag, cancellationToken)
.ConfigureAwait(false);
dryRun, strict, contentCache, declarationContext, cancellationToken).ConfigureAwait(false);
retired += outcome.Retired;
foreach (WoTResourceLoadResultDataType result in outcome.Results)
@@ -222,14 +213,12 @@ namespace Opc.Ua.WotCon.Server.Materialization
}
projections.AddRange(outcome.Projections);
}
rfDiag.Looped(results.Count); // [DEBUG-G10-RF1]
if (!dryRun && projections.Count > 0)
{
await m_registry.ApplyProjectionResultsAsync(
projections, cancellationToken).ConfigureAwait(false);
}
rfDiag.Applied(); // [DEBUG-G10-RF1]
if (!dryRun)
{
m_generation = newGeneration;
@@ -264,7 +253,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
Summary = summary
});
rfDiag.Done(rejected: false); // [DEBUG-G10-RF1]
return new WotRefreshResult(
summary, results.ToImmutable(), dryRun ? 0u : newGeneration);
}
@@ -275,14 +263,7 @@ namespace Opc.Ua.WotCon.Server.Materialization
}
finally
{
try // [DEBUG-G10-RF1]
{
rfDiag?.Finish(cancellationToken.IsCancellationRequested); // [DEBUG-G10-RF1]
}
finally // [DEBUG-G10-RF1]
{
EndOperation();
}
EndOperation();
}
}
@@ -491,11 +472,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
}
}
/// <summary>
/// [DEBUG-G10-RF1] Temporary diagnostics logger for refresh timing.
/// </summary>
internal Microsoft.Extensions.Logging.ILogger? DiagLogger { get; set; }
/// <summary>
/// Releases the mutex used to serialise refreshes.
/// </summary>
@@ -571,34 +547,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
bool strict,
Dictionary<string, ByteString> contentCache,
WotProjectionDeclarationContext declarationContext,
WotRefreshDiag? rfDiag, // [DEBUG-G10-RF1]
CancellationToken cancellationToken)
{
WotClosureDiag? rfClosure = rfDiag?.BeginClosure(); // [DEBUG-G10-RF1]
try // [DEBUG-G10-RF1]
{
ClosureOutcome outcome = await ProcessClosureCoreAsync(
snapshot, closure, generation, force, dryRun, strict, contentCache,
declarationContext, rfClosure, cancellationToken).ConfigureAwait(false);
rfClosure?.Done(); // [DEBUG-G10-RF1]
return outcome;
}
finally // [DEBUG-G10-RF1]
{
rfClosure?.Finish(cancellationToken.IsCancellationRequested); // [DEBUG-G10-RF1]
}
}
private async ValueTask<ClosureOutcome> ProcessClosureCoreAsync(
WotRegistrySnapshot snapshot,
WotDependencyClosure closure,
uint generation,
bool force,
bool dryRun,
bool strict,
Dictionary<string, ByteString> contentCache,
WotProjectionDeclarationContext declarationContext,
WotClosureDiag? rfClosure, // [DEBUG-G10-RF1]
CancellationToken cancellationToken)
{
ImmutableArray<WoTResourceLoadResultDataType>.Builder results =
@@ -677,7 +625,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
var requiredNamespaces = new HashSet<string>(StringComparer.Ordinal);
var ownedNamespaces = new HashSet<string>(StringComparer.Ordinal);
WotClosureDiag.LoopStart(rfClosure, members.Count); // [DEBUG-G10-RF1]
foreach (WotResource member in members)
{
WotResourceVersion? version = member.DefaultVersion;
@@ -707,15 +654,10 @@ namespace Opc.Ua.WotCon.Server.Materialization
// sources (Section 12.6), never as affordance Nodes of its own. It
// is deferred here and materialized after its sources, whose
// materialized roots the View resolves against.
long rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
ByteString memberContent = await ReadCachedContentAsync(
contentCache, version, cancellationToken)
.ConfigureAwait(false);
WotClosureDiag.Add(rfClosure, WotClosureDiag.Read, rfT); // [DEBUG-G10-RF1]
rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
bool rfIsProjection = IsProjectionResource(memberContent); // [DEBUG-G10-RF1]
WotClosureDiag.Add(rfClosure, WotClosureDiag.Parse, rfT); // [DEBUG-G10-RF1]
if (rfIsProjection)
if (IsProjectionResource(memberContent))
{
if (member.Enabled)
{
@@ -724,14 +666,11 @@ namespace Opc.Ua.WotCon.Server.Materialization
continue;
}
rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
(UANodeSet? nodeSet, ExpandedNodeId root, string? conversionError, WoTPhaseEnum failurePhase) =
await TryConvertAsync(member, snapshot, contentCache, cancellationToken)
.ConfigureAwait(false);
WotClosureDiag.Add(rfClosure, WotClosureDiag.Convert, rfT); // [DEBUG-G10-RF1]
if (nodeSet is not null && m_nodeSetContributors.Length > 0)
{
rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
// Contributors run after conversion and before any variable is created, which
// is when a programmatically discovered DataType (a controller UDT, say) has to
// exist for a uav:mapByFieldPath mapping to resolve against it.
@@ -741,7 +680,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
.ContributeAsync(member, nodeSet, cancellationToken)
.ConfigureAwait(false);
}
WotClosureDiag.Add(rfClosure, WotClosureDiag.Contrib, rfT); // [DEBUG-G10-RF1]
}
if (nodeSet is null)
{
@@ -780,17 +718,13 @@ namespace Opc.Ua.WotCon.Server.Materialization
retiredMembers);
}
rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
declarationContext.AddNodeSet(member.Xid, nodeSet, root, memberContent);
WotClosureDiag.Add(rfClosure, WotClosureDiag.DeclAdd, rfT); // [DEBUG-G10-RF1]
if (member.Enabled)
{
rfT = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
WotBindingPlanRequest planRequest = (await BuildPlanRequestAsync(
member, version, memberContent, snapshot, contentCache, cancellationToken)
.ConfigureAwait(false))
.WithProjectionRoot(root);
WotClosureDiag.Add(rfClosure, WotClosureDiag.PlanReq, rfT); // [DEBUG-G10-RF1]
preparedPlans.Add((member, planRequest));
}
@@ -803,18 +737,12 @@ namespace Opc.Ua.WotCon.Server.Materialization
CollectRequiredNamespaces(nodeSet, requiredNamespaces, ownedNamespaces);
}
WotClosureDiag.LoopEnd(
rfClosure, convertedSources.Count, projectionMembers.Count, preparedPlans.Count); // [DEBUG-G10-RF1]
long rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
try
{
sources.AddRange(CoalesceProjectionSources(convertedSources));
WotClosureDiag.Add(rfClosure, WotClosureDiag.Coalesce, rfPhase); // [DEBUG-G10-RF1]
WotClosureDiag.Sources(rfClosure, sources.Count); // [DEBUG-G10-RF1]
}
catch (ServiceResultException exception)
{
WotClosureDiag.Add(rfClosure, WotClosureDiag.Coalesce, rfPhase); // [DEBUG-G10-RF1]
foreach (WotResource member in activeMembers)
{
results.Add(FailResult(member, generation, WoTPhaseEnum.Projection, exception.Message));
@@ -832,12 +760,10 @@ namespace Opc.Ua.WotCon.Server.Materialization
// sources so they materialize before the documents that reference them. A namespace
// that stays unresolved is reported, never silently dropped: the projection then fails
// with a message naming exactly what is missing.
rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
(ImmutableArray<WotProjectionSource> resolved, ImmutableArray<string> unresolved) =
await ResolveDependencyModelsAsync(
requiredNamespaces, ownedNamespaces, declarationContext, cancellationToken)
.ConfigureAwait(false);
WotClosureDiag.Add(rfClosure, WotClosureDiag.Resolve, rfPhase); // [DEBUG-G10-RF1]
if (!resolved.IsDefaultOrEmpty)
{
sources.InsertRange(0, resolved);
@@ -858,11 +784,9 @@ namespace Opc.Ua.WotCon.Server.Materialization
// classifying any root, including ownership across partition order.
foreach ((WotResource member, WotBindingPlanRequest request) in preparedPlans)
{
rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
bool isDeclaration = await declarationContext.IsDeclarationAsync(member, cancellationToken)
.ConfigureAwait(false);
WotBindingPlan plan = m_binders.Prepare(request.WithDeclarationContext(isDeclaration));
WotClosureDiag.Add(rfClosure, WotClosureDiag.Prepare, rfPhase); // [DEBUG-G10-RF1]
bindingPlans.Add(plan);
if (!plan.FullySupported)
{
@@ -925,7 +849,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
WotProjectionHandle? handle = tracked?.Handle;
if (sources.Count > 0)
{
rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
try
{
if (tracked?.Handle is null)
@@ -943,11 +866,9 @@ namespace Opc.Ua.WotCon.Server.Materialization
handle = await m_host.ShadowReloadAsync(
tracked.Handle, document, cancellationToken).ConfigureAwait(false);
}
WotClosureDiag.Add(rfClosure, WotClosureDiag.HostAdd, rfPhase); // [DEBUG-G10-RF1]
}
catch (Exception ex) when (ex is not OperationCanceledException)
{
WotClosureDiag.Add(rfClosure, WotClosureDiag.HostAdd, rfPhase); // [DEBUG-G10-RF1]
// Projection failed: retain the previous active generation and its
// active-member binding plans. Inactive dependency-only members
// were retired before the attempt and must not be marked failed.
@@ -981,12 +902,10 @@ namespace Opc.Ua.WotCon.Server.Materialization
var viewHandles = new List<WotViewProjectionHandle>();
if (projectionMembers.Count > 0)
{
rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
await MaterializeProjectionViewsAsync(
snapshot, projectionMembers, perMemberRoot, generation,
projectionXids, viewResults, viewProjections, viewHandles,
contentCache, cancellationToken).ConfigureAwait(false);
WotClosureDiag.Add(rfClosure, WotClosureDiag.Views, rfPhase); // [DEBUG-G10-RF1]
}
// The shadow switch (or first add) succeeded. On an update, retire the
@@ -997,7 +916,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
// shared between the old and new plan sets continuously bound.
if (tracked is not null)
{
rfPhase = WotClosureDiag.Now(rfClosure); // [DEBUG-G10-RF1]
foreach (WotBindingPlan plan in tracked.BindingPlans)
{
await m_binders.DeactivateAsync(plan, cancellationToken).ConfigureAwait(false);
@@ -1007,7 +925,6 @@ namespace Opc.Ua.WotCon.Server.Materialization
await m_viewHost.RemoveAsync(viewHandle, cancellationToken)
.ConfigureAwait(false);
}
WotClosureDiag.Add(rfClosure, WotClosureDiag.Deactivate, rfPhase); // [DEBUG-G10-RF1]
}
m_closures[closure.Key] = new ClosureState
src/Opc.Ua.WotCon.Server/Materialization/WotRefreshDiag.cs
-469
View File
@@ -1,469 +0,0 @@
/* ========================================================================
* Copyright (c) 2005-2026 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.Diagnostics;
using System.Threading;
using Microsoft.Extensions.Logging;
namespace Opc.Ua.WotCon.Server.Materialization
{
/// <summary>
/// [DEBUG-G10-RF1] Temporary diagnostics-only timing collector for one coordinator refresh.
/// Records numeric phase timings and counts only. Remove together with every
/// [DEBUG-G10-RF1] marker before the final repair.
/// </summary>
internal sealed class WotRefreshDiag
{
/// <summary>
/// Starts timing a refresh and emits the queue marker when the mutex is already held.
/// </summary>
public WotRefreshDiag(ILogger? logger, int mutexAvailable, int kind)
{
m_logger = logger;
m_kind = kind;
m_id = Interlocked.Increment(ref s_nextId);
m_entry = Stopwatch.GetTimestamp();
m_waiting = Interlocked.Increment(ref s_waiting);
if (mutexAvailable == 0)
{
m_logger?.RefreshQueued(m_id, m_kind, m_waiting);
}
}
/// <summary>
/// Marks the mutex as acquired.
/// </summary>
public void Acquired()
{
Interlocked.Decrement(ref s_waiting);
m_acquired = Stopwatch.GetTimestamp();
}
/// <summary>
/// Marks the end of the closure build phase.
/// </summary>
public void Built(int enabled, int closures)
{
m_built = Stopwatch.GetTimestamp();
m_enabled = enabled;
m_closures = closures;
}
/// <summary>
/// Marks the end of the native partition phase.
/// </summary>
public void Native()
{
m_native = Stopwatch.GetTimestamp();
}
/// <summary>
/// Marks the end of the retirement reconcile phase.
/// </summary>
public void Retired()
{
m_retired = Stopwatch.GetTimestamp();
}
/// <summary>
/// Marks the end of the closure loop.
/// </summary>
public void Looped(int results)
{
m_looped = Stopwatch.GetTimestamp();
m_results = results;
}
/// <summary>
/// Marks the end of the apply phase.
/// </summary>
public void Applied()
{
m_applied = Stopwatch.GetTimestamp();
}
/// <summary>
/// Marks the refresh as returning a result.
/// </summary>
public void Done(bool rejected)
{
m_outcome = rejected ? 2 : 1;
}
/// <summary>
/// Starts the aggregate part timing of one closure of this refresh.
/// </summary>
public WotClosureDiag BeginClosure()
{
return new WotClosureDiag(m_logger, m_id, m_kind);
}
/// <summary>
/// Emits the single summary line.
/// </summary>
public void Finish(bool cancellationRequested)
{
long end = Stopwatch.GetTimestamp();
if (m_acquired == 0)
{
Interlocked.Decrement(ref s_waiting);
}
string outcome = m_outcome switch
{
1 => "completed",
2 => "rejected",
_ => cancellationRequested ? "cancelled" : "faulted"
};
long acquired = m_acquired == 0 ? end : m_acquired;
long built = m_built == 0 ? 0 : Ms(acquired, m_built);
m_logger?.RefreshSummary(
m_id,
m_kind,
outcome,
Ms(m_entry, acquired),
built,
m_native == 0 ? 0 : Ms(m_built, m_native),
m_retired == 0 ? 0 : Ms(m_native, m_retired),
m_looped == 0 ? 0 : Ms(m_retired, m_looped),
m_applied == 0 ? 0 : Ms(m_looped, m_applied),
Ms(m_entry, end),
m_enabled,
m_closures,
m_results);
}
private static long Ms(long from, long to)
{
return (to - from) * 1000 / Stopwatch.Frequency;
}
private static int s_nextId;
private static int s_waiting;
private readonly ILogger? m_logger;
private readonly int m_id;
private readonly int m_kind;
private readonly int m_waiting;
private readonly long m_entry;
private long m_acquired;
private long m_built;
private long m_native;
private long m_retired;
private long m_looped;
private long m_applied;
private int m_enabled;
private int m_closures;
private int m_results;
private int m_outcome;
}
/// <summary>
/// [DEBUG-G10-RF1] Temporary diagnostics-only aggregate part timing for one closure.
/// Parts are disjoint raw-tick accumulators converted to milliseconds once at the end;
/// time not inside any part is reported as unattributed. Numeric values only.
/// </summary>
internal sealed class WotClosureDiag
{
/// <summary>
/// Creates the closure collector.
/// </summary>
public WotClosureDiag(ILogger? logger, int refreshId, int kind)
{
m_logger = logger;
m_id = refreshId;
m_kind = kind;
m_entry = Stopwatch.GetTimestamp();
}
/// <summary>
/// Reads the timestamp, or zero when diagnostics are disabled.
/// </summary>
public static long Now(WotClosureDiag? diag)
{
return diag is null ? 0 : Stopwatch.GetTimestamp();
}
/// <summary>
/// Adds the ticks elapsed since the start timestamp to a part.
/// </summary>
public static void Add(WotClosureDiag? diag, int part, long start)
{
if (diag is not null)
{
diag.m_ticks[part] += Stopwatch.GetTimestamp() - start;
}
}
/// <summary>
/// Records the member loop boundaries and counts.
/// </summary>
public static void LoopStart(WotClosureDiag? diag, int members)
{
if (diag is not null)
{
diag.m_members = members;
diag.m_loopStart = Stopwatch.GetTimestamp();
}
}
/// <summary>
/// Records the normal end of the member loop.
/// </summary>
public static void LoopEnd(
WotClosureDiag? diag,
int converted,
int projections,
int plans)
{
if (diag is not null)
{
diag.m_loopEnd = Stopwatch.GetTimestamp();
diag.m_converted = converted;
diag.m_projections = projections;
diag.m_plans = plans;
}
}
/// <summary>
/// Records the number of coalesced sources.
/// </summary>
public static void Sources(WotClosureDiag? diag, int sources)
{
if (diag is not null)
{
diag.m_sources = sources;
}
}
/// <summary>
/// Marks the closure as returning normally.
/// </summary>
public void Done()
{
m_completed = true;
}
/// <summary>
/// Emits the single parts-summary line.
/// </summary>
public void Finish(bool cancellationRequested)
{
long end = Stopwatch.GetTimestamp();
long total = end - m_entry;
long parts = 0;
for (int i = 0; i < m_ticks.Length; i++)
{
parts += m_ticks[i];
}
bool looped = m_loopEnd != 0;
long loopTicks = looped ? m_loopEnd - m_loopStart : 0;
long loopParts = m_ticks[Read] + m_ticks[Parse] + m_ticks[Convert] + m_ticks[Contrib] +
m_ticks[DeclAdd] + m_ticks[PlanReq];
string outcome = m_completed ? "completed" : cancellationRequested ? "cancelled" : "faulted";
m_logger?.ClosureParts(
m_id,
m_kind,
outcome,
m_members,
m_converted,
m_projections,
m_sources,
m_plans,
Ms(m_ticks[Read]),
Ms(m_ticks[Parse]),
Ms(m_ticks[Convert]),
Ms(m_ticks[Contrib]),
Ms(m_ticks[DeclAdd]),
Ms(m_ticks[PlanReq]),
looped ? Ms(loopTicks) : -1,
looped ? Ms(loopTicks - loopParts) : -1,
Ms(m_ticks[Coalesce]),
Ms(m_ticks[Resolve]),
Ms(m_ticks[Prepare]),
Ms(m_ticks[HostAdd]),
Ms(m_ticks[Views]),
Ms(m_ticks[Deactivate]),
Ms(total - parts),
Ms(total));
}
private static long Ms(long ticks)
{
return ticks * 1000 / Stopwatch.Frequency;
}
/// <summary>
/// Part index of reading the member content.
/// </summary>
public const int Read = 0;
/// <summary>
/// Part index of the projection-document check (full parse).
/// </summary>
public const int Parse = 1;
/// <summary>
/// Part index of the document conversion.
/// </summary>
public const int Convert = 2;
/// <summary>
/// Part index of the NodeSet contributors.
/// </summary>
public const int Contrib = 3;
/// <summary>
/// Part index of adding the NodeSet to the declaration context.
/// </summary>
public const int DeclAdd = 4;
/// <summary>
/// Part index of building the binding plan request.
/// </summary>
public const int PlanReq = 5;
/// <summary>
/// Part index of coalescing the projection sources.
/// </summary>
public const int Coalesce = 6;
/// <summary>
/// Part index of resolving dependency models.
/// </summary>
public const int Resolve = 7;
/// <summary>
/// Part index of the declaration check and binding plan preparation.
/// </summary>
public const int Prepare = 8;
/// <summary>
/// Part index of the host add or reload.
/// </summary>
public const int HostAdd = 9;
/// <summary>
/// Part index of the projection view materialization.
/// </summary>
public const int Views = 10;
/// <summary>
/// Part index of deactivating the previous plans and views.
/// </summary>
public const int Deactivate = 11;
private readonly ILogger? m_logger;
private readonly int m_id;
private readonly int m_kind;
private readonly long m_entry;
private readonly long[] m_ticks = new long[12];
private long m_loopStart;
private long m_loopEnd;
private int m_members;
private int m_converted;
private int m_projections;
private int m_sources;
private int m_plans;
private bool m_completed;
}
/// <summary>
/// [DEBUG-G10-RF1] Holds temporary source-generated refresh timing log messages.
/// </summary>
internal static partial class WotRefreshDiagLog
{
/// <summary>
/// Logs that a refresh is queued behind another coordinator operation.
/// </summary>
[LoggerMessage(EventId = WotConServerEventIds.WotRefreshDiag + 0, Level = LogLevel.Warning,
Message = "[DEBUG-G10-RF1] refresh queued id={RefreshId} kind={Kind} waiting={Waiting}")]
public static partial void RefreshQueued(this ILogger logger, int refreshId, int kind, int waiting);
/// <summary>
/// Logs the aggregate timing of one refresh.
/// </summary>
[LoggerMessage(EventId = WotConServerEventIds.WotRefreshDiag + 1, Level = LogLevel.Warning,
Message = "[DEBUG-G10-RF1] refresh id={RefreshId} kind={Kind} outcome={Outcome} waitMs={WaitMs} " +
"buildMs={BuildMs} nativeMs={NativeMs} retireMs={RetireMs} loopMs={LoopMs} " +
"applyMs={ApplyMs} totalMs={TotalMs} enabled={Enabled} closures={Closures} results={Results}")]
public static partial void RefreshSummary(
this ILogger logger,
int refreshId,
int kind,
string outcome,
long waitMs,
long buildMs,
long nativeMs,
long retireMs,
long loopMs,
long applyMs,
long totalMs,
int enabled,
int closures,
int results);
/// <summary>
/// Logs the aggregate part timing of one closure.
/// </summary>
[LoggerMessage(EventId = WotConServerEventIds.WotRefreshDiag + 2, Level = LogLevel.Warning,
Message = "[DEBUG-G10-RF1] closure parts id={RefreshId} kind={Kind} outcome={Outcome} " +
"members={Members} converted={Converted} projections={Projections} sources={Sources} " +
"plans={Plans} readMs={ReadMs} parseMs={ParseMs} convertMs={ConvertMs} " +
"contribMs={ContribMs} declAddMs={DeclAddMs} planReqMs={PlanReqMs} memberLoopMs={MemberLoopMs} " +
"loopResidualMs={LoopResidualMs} coalesceMs={CoalesceMs} resolveMs={ResolveMs} " +
"prepareMs={PrepareMs} hostAddMs={HostAddMs} viewsMs={ViewsMs} deactivateMs={DeactivateMs} " +
"unattributedMs={UnattributedMs} closureMs={ClosureMs}")]
public static partial void ClosureParts(
this ILogger logger,
int refreshId,
int kind,
string outcome,
int members,
int converted,
int projections,
int sources,
int plans,
long readMs,
long parseMs,
long convertMs,
long contribMs,
long declAddMs,
long planReqMs,
long memberLoopMs,
long loopResidualMs,
long coalesceMs,
long resolveMs,
long prepareMs,
long hostAddMs,
long viewsMs,
long deactivateMs,
long unattributedMs,
long closureMs);
}
}
src/Opc.Ua.WotCon.Server/WotRegistryNodeManager.cs
-1
View File
@@ -83,7 +83,6 @@ namespace Opc.Ua.WotCon.Server
Coordinator.StrictBindings = options.StrictBindings;
Coordinator.RetirementPolicy = options.RetirementPolicy;
Coordinator.ServerNamespaceUris = server.NamespaceUris;
Coordinator.DiagLogger = server.Telemetry.CreateLogger<WotRegistryNodeManager>(); // [DEBUG-G10-RF1]
// WoT Binding Section 5.1.5 makes a loaded AddressSpace the second
// half of the local context. This is the first point at which it