P0 SBO Enhanced: per-invoke TPKT send / confirmed response / decode timing (no safety change)

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<T> MeasureServiceAsync<T>(Func<Task<T>> 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")
         };
     }
 

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<MmsWriteResult> 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,28 +669,51 @@ public async Task<byte[]> SendPresentationPayloadAsync(ReadOnlyMemory<byte> payl
     private async Task<byte[]> SendConfirmedPresentationPayloadAsync(
         ReadOnlyMemory<byte> payload,
         int expectedInvokeId,
-        CancellationToken cancellationToken)
+        CancellationToken cancellationToken,
+        Action<TimeSpan, TimeSpan>? 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)
         {
             cancellationToken.ThrowIfCancellationRequested();
 
             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<byte[]> SendConfirmedPresentationPayloadAsync(
             if (route.Action == MmsReceiveRouteAction.QueuedConfirmedResult)
             {
                 if (_receiveRouter.TryDequeueConfirmedResult(expectedInvokeId, out var matched))
+                {
+                    CaptureCompleteTiming();
                     return matched.PresentationPayload;
-
+                }
                 continue;
             }
 
+            CaptureCompleteTiming();
             return route.Envelope.PresentationPayload;
         }
     }

src/AR.Iec61850/Mms/MmsWrite.cs

@@ -17,6 +17,12 @@ public sealed class MmsWriteResult
     public IReadOnlyList<MmsWriteAccessResult> AccessResults { get; init; } = Array.Empty<MmsWriteAccessResult>();
     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

tests/AR.Iec61850.Tests/Control/P0SboServiceWireStagesTests.cs

@@ -0,0 +1,71 @@
+using System.Reflection;
+using AR.Iec61850.Mms;
+
+namespace AR.Iec61850.Tests.Control;
+
+/// <summary>
+/// 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.
+/// </summary>
+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<TimeSpan, TimeSpan>), 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);
+    }
+}