From f2b18df8763b166275c2338941170d314acf62b3 Mon Sep 17 00:00:00 2001 From: Ari Sulistiono Date: Wed, 21 Oct 2026 18:37:47 +0700 Subject: [PATCH 1/4] feat(control-telemetry): measure exact confirmed MMS send, response wait and decode without altering command semantics --- src/AR.Iec61850/Mms/MmsWrite.cs | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/src/AR.Iec61850/Mms/MmsWrite.cs b/src/AR.Iec61850/Mms/MmsWrite.cs index 4b23ba63..80df52e6 100644 --- a/src/AR.Iec61850/Mms/MmsWrite.cs +++ b/src/AR.Iec61850/Mms/MmsWrite.cs @@ -17,6 +17,12 @@ public sealed class MmsWriteResult public IReadOnlyList AccessResults { get; init; } = Array.Empty(); public string Message { get; init; } = string.Empty; public string ResponseHexPreview { get; init; } = string.Empty; + + // Time inside the client process, not on-the-wire latency. Populated + // only when this write has a confirmed MMS response. + public TimeSpan? TpktSendElapsed { get; internal set; } + public TimeSpan? ConfirmedResponseWaitElapsed { get; internal set; } + public TimeSpan? ResponseDecodeElapsed { get; internal set; } } public static class MmsWriteRequest From 3850e7ba64460ac8e28c40a633ce0f0422a9a486 Mon Sep 17 00:00:00 2001 From: Ari Sulistiono Date: Wed, 21 Oct 2026 18:37:50 +0700 Subject: [PATCH 2/4] feat(control-telemetry): measure exact confirmed MMS send, response wait and decode without altering command semantics --- src/AR.Iec61850/Mms/MmsClientSession.cs | 42 +++++++++++++++++++++++-- 1 file changed, 39 insertions(+), 3 deletions(-) diff --git a/src/AR.Iec61850/Mms/MmsClientSession.cs b/src/AR.Iec61850/Mms/MmsClientSession.cs index 0ca63d33..d783b5e7 100644 --- a/src/AR.Iec61850/Mms/MmsClientSession.cs +++ b/src/AR.Iec61850/Mms/MmsClientSession.cs @@ -1,6 +1,7 @@ using AR.Iec61850.Acse; using AR.Iec61850.Diagnostics; using AR.Iec61850.Osi; +using System.Diagnostics; namespace AR.Iec61850.Mms; @@ -561,8 +562,17 @@ private async Task WriteSingleVariableCoreAsync( try { - var response = await SendConfirmedPresentationPayloadAsync(request, invokeId, cancellationToken).ConfigureAwait(false); + TimeSpan? sendDuration = null; + TimeSpan? responseDuration = null; + var response = await SendConfirmedPresentationPayloadAsync( + request, invokeId, cancellationToken, + (send, wait) => { sendDuration = send; responseDuration = wait; }) + .ConfigureAwait(false); + var decodeStart = Stopwatch.GetTimestamp(); var result = MmsWriteResponseDecoder.Decode(response, invokeId); + result.TpktSendElapsed = sendDuration; + result.ConfirmedResponseWaitElapsed = responseDuration; + result.ResponseDecodeElapsed = Stopwatch.GetElapsedTime(decodeStart); LastReadResponseHex = result.ResponseHexPreview; return result; } @@ -659,21 +669,43 @@ public async Task SendPresentationPayloadAsync(ReadOnlyMemory payl private async Task SendConfirmedPresentationPayloadAsync( ReadOnlyMemory payload, int expectedInvokeId, - CancellationToken cancellationToken) + CancellationToken cancellationToken, + Action? onCompletedTiming = null) { if (!IsTransportConnected) throw new InvalidOperationException("Native IEC 61850 transport is not connected."); + // No global mutable timestamps: the closure and invoke ID belong to this + // one request. Concurrent confirmed reads cannot overwrite its evidence. + // The send measurement includes the local TPKT send gate and stream write. + // Response-wait begins AFTER the completed local send; it is NOT pure + // wire RTT, nor does it isolate remote IED decision time. + var sendStarted = onCompletedTiming is null ? 0L : Stopwatch.GetTimestamp(); + long sentAt = 0L; + void CaptureCompleteTiming() + { + if (onCompletedTiming is null || sentAt == 0) + return; + onCompletedTiming( + Stopwatch.GetElapsedTime(sendStarted, sentAt), + Stopwatch.GetElapsedTime(sentAt)); + } + if (_receivePump.IsRunning) { using var pending = _receivePump.RegisterConfirmedOperation(expectedInvokeId); await _cotp.SendDataAsync(payload, cancellationToken).ConfigureAwait(false); + if (onCompletedTiming is not null) + sentAt = Stopwatch.GetTimestamp(); var envelope = await pending.WaitAsync(cancellationToken).ConfigureAwait(false); + CaptureCompleteTiming(); LastReceiveRoutingSummary = $"Receive pump completed {envelope.Kind} for invokeID={expectedInvokeId}. queuedReports={_receivePump.QueuedInformationReportCount}."; return envelope.PresentationPayload; } await _cotp.SendDataAsync(payload, cancellationToken).ConfigureAwait(false); + if (onCompletedTiming is not null) + sentAt = Stopwatch.GetTimestamp(); while (true) { @@ -681,6 +713,7 @@ private async Task SendConfirmedPresentationPayloadAsync( if (_receiveRouter.TryDequeueConfirmedResult(expectedInvokeId, out var queued)) { + CaptureCompleteTiming(); LastReceiveRoutingSummary = $"Dequeued queued {queued.Kind} for invokeID={expectedInvokeId}."; return queued.PresentationPayload; } @@ -696,11 +729,14 @@ private async Task SendConfirmedPresentationPayloadAsync( if (route.Action == MmsReceiveRouteAction.QueuedConfirmedResult) { if (_receiveRouter.TryDequeueConfirmedResult(expectedInvokeId, out var matched)) + { + CaptureCompleteTiming(); return matched.PresentationPayload; - + } continue; } + CaptureCompleteTiming(); return route.Envelope.PresentationPayload; } } From 695df4e60cc96c296a51b3d210dc0ea073d3a3a0 Mon Sep 17 00:00:00 2001 From: Ari Sulistiono Date: Wed, 21 Oct 2026 18:37:53 +0700 Subject: [PATCH 3/4] feat(control-telemetry): measure exact confirmed MMS send, response wait and decode without altering command semantics --- .../Control/Iec61850ControlObjectSession.cs | 20 +++++++++++++++++-- 1 file changed, 18 insertions(+), 2 deletions(-) diff --git a/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs b/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs index 1bd7b268..55f911f3 100644 --- a/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs +++ b/src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs @@ -30,6 +30,7 @@ private sealed class AssociationControlState private DateTimeOffset _serviceStartedUtc; private TimeSpan _serviceElapsed; private long _serviceCompletedTimestamp; + private MmsWriteResult? _lastMeasuredWrite; internal Iec61850ControlObjectSession( @@ -792,7 +793,16 @@ private async Task MeasureServiceAsync(Func> service) { _serviceStartedUtc = DateTimeOffset.UtcNow; var started = Stopwatch.GetTimestamp(); - try { return await service().ConfigureAwait(false); } + _lastMeasuredWrite = null; + try + { + var result = await service().ConfigureAwait(false); + // Only the exact MMS write result which produced this step can + // supply transport timing. Never borrow another invoke ID's stats. + if (result is MmsWriteResult write) + _lastMeasuredWrite = write; + return result; + } finally { _serviceElapsed = Stopwatch.GetElapsedTime(started); @@ -827,6 +837,12 @@ private Iec61850ControlWireStep BuildWireStep( }; var graceBudget = action == Iec61850ControlAction.SelectWithValue ? _options.ApplicationErrorGracePeriod.TotalMilliseconds : 0d; + var transportStages = _lastMeasuredWrite is + { TpktSendElapsed: { } send, ConfirmedResponseWaitElapsed: { } response, + ResponseDecodeElapsed: { } decode } + ? FormattableString.Invariant( + $"tpktSendMs={send.TotalMilliseconds:0.###}; confirmedResponseWaitMs={response.TotalMilliseconds:0.###}; mmsDecodeMs={decode.TotalMilliseconds:0.###}") + : "transportStages=unavailable"; return new Iec61850ControlWireStep { Action = action, @@ -835,7 +851,7 @@ private Iec61850ControlWireStep BuildWireStep( RequestHex = _transport.LastRequestHex, ResponseHex = _transport.LastResponseHex, Detail = FormattableString.Invariant( - $"{detail} serviceStartedUtc={_serviceStartedUtc:O}; serviceMs={_serviceElapsed.TotalMilliseconds:0.###}; postResponseWaitMs={Stopwatch.GetElapsedTime(_serviceCompletedTimestamp).TotalMilliseconds:0.###}; postResponseStage={postResponseStage}; configuredApplicationErrorGraceMs={graceBudget:0.###}; timingScope=local-service-not-wire") + $"{detail} serviceStartedUtc={_serviceStartedUtc:O}; serviceMs={_serviceElapsed.TotalMilliseconds:0.###}; postResponseWaitMs={Stopwatch.GetElapsedTime(_serviceCompletedTimestamp).TotalMilliseconds:0.###}; postResponseStage={postResponseStage}; configuredApplicationErrorGraceMs={graceBudget:0.###}; {transportStages}; timingScope=local-service-not-wire") }; } From 4ed76ccd11b763dcd847395f6ef45273db3f5c9c Mon Sep 17 00:00:00 2001 From: Ari Sulistiono Date: Wed, 21 Oct 2026 18:38:50 +0700 Subject: [PATCH 4/4] test(control): pin per-invoke opt-in send/confirmed-response stages and unchanged enhanced guards --- .../Control/P0SboServiceWireStagesTests.cs | 71 +++++++++++++++++++ 1 file changed, 71 insertions(+) create mode 100644 tests/AR.Iec61850.Tests/Control/P0SboServiceWireStagesTests.cs diff --git a/tests/AR.Iec61850.Tests/Control/P0SboServiceWireStagesTests.cs b/tests/AR.Iec61850.Tests/Control/P0SboServiceWireStagesTests.cs new file mode 100644 index 00000000..faad0d88 --- /dev/null +++ b/tests/AR.Iec61850.Tests/Control/P0SboServiceWireStagesTests.cs @@ -0,0 +1,71 @@ +using System.Reflection; +using AR.Iec61850.Mms; + +namespace AR.Iec61850.Tests.Control; + +/// +/// Mechanical and data-contract guards for the opt-in client-side phase timer. +/// These tests do NOT simulate breaker operation or claim measured wire RTT. +/// +public sealed class P0SboServiceWireStagesTests +{ + [Fact] + public void MmsWriteResult_ExposesOptionalPerRequestTimingsWithoutFabricatedZero() + { + var failed = new MmsWriteResult + { + IsSuccess = false, + Message = "simulated timeout before response" + }; + Assert.Null(failed.TpktSendElapsed); + Assert.Null(failed.ConfirmedResponseWaitElapsed); + Assert.Null(failed.ResponseDecodeElapsed); + } + + [Fact] + public void ConfirmedMmsTimer_IsPerInvokeOptInNotGlobalSessionStopwatch() + { + var method = typeof(MmsClientSession).GetMethod( + "SendConfirmedPresentationPayloadAsync", + BindingFlags.Instance | BindingFlags.NonPublic); + Assert.NotNull(method); + var parameters = method.GetParameters(); + Assert.Equal(4, parameters.Length); + Assert.Equal(typeof(int), parameters[1].ParameterType); + Assert.Equal(typeof(CancellationToken), parameters[2].ParameterType); + Assert.Equal(typeof(Action), parameters[3].ParameterType); + Assert.True(parameters[3].IsOptional); + } + + [Fact] + public void TelemetryCannotTurnOffLastApplErrorOrPositiveTermination() + { + var session = ReadRepoFile("src/AR.Iec61850/Control/Iec61850ControlObjectSession.cs"); + var transport = ReadRepoFile("src/AR.Iec61850/Mms/MmsClientSession.cs"); + var tcp = ReadRepoFile("src/AR.Iec61850/Osi/TpktClient.cs"); + + Assert.Contains("WaitForApplicationErrorAsync(", session, StringComparison.Ordinal); + Assert.Contains("_options.ApplicationErrorGracePeriod", session, StringComparison.Ordinal); + Assert.Contains("WaitForTerminationAsync(reports, remaining, cancellationToken)", session, + StringComparison.Ordinal); + Assert.Contains("tpktSendMs=", session, StringComparison.Ordinal); + Assert.Contains("confirmedResponseWaitMs=", session, StringComparison.Ordinal); + Assert.Contains("mmsDecodeMs=", session, StringComparison.Ordinal); + Assert.Contains("RegisterConfirmedOperation(expectedInvokeId)", transport, + StringComparison.Ordinal); + Assert.Contains("new TcpClient { NoDelay = true }", tcp, StringComparison.Ordinal); + } + + private static string ReadRepoFile(string path) + { + var folder = new DirectoryInfo(AppContext.BaseDirectory); + while (folder is not null) + { + var file = Path.Combine(folder.FullName, path.Replace('/', Path.DirectorySeparatorChar)); + if (File.Exists(file)) + return File.ReadAllText(file); + folder = folder.Parent; + } + throw new FileNotFoundException(path); + } +}