still honing in on the write stall; measure/record write and flush excesses

src/StackExchange.Redis/PhysicalBridge.cs

@@ -643,40 +643,57 @@ private WriteResult WriteMessageInsideLock(PhysicalConnection physical, Message
                 Multiplexer?.OnInfoMessage($"reentrant call to WriteMessageTakingWriteLock for {message.CommandAndKey}, {existingMessage.CommandAndKey} is still active");
                 return WriteResult.NoConnectionAvailable;
             }
-            physical.SetWriting();
-            var messageIsSent = false;
-            if (message is IMultiMessage)
+            int startWriteTime = Environment.TickCount;
+            try
             {
-                SelectDatabaseInsideWriteLock(physical, message); // need to switch database *before* the transaction
-                foreach (var subCommand in ((IMultiMessage)message).GetMessages(physical))
+                physical.SetWriting();
+                var messageIsSent = false;
+                if (message is IMultiMessage)
                 {
-                    result = WriteMessageToServerInsideWriteLock(physical, subCommand);
-                    if (result != WriteResult.Success)
+                    SelectDatabaseInsideWriteLock(physical, message); // need to switch database *before* the transaction
+                    foreach (var subCommand in ((IMultiMessage)message).GetMessages(physical))
+                    {
+                        result = WriteMessageToServerInsideWriteLock(physical, subCommand);
+                        if (result != WriteResult.Success)
+                        {
+                            // we screwed up; abort; note that WriteMessageToServer already
+                            // killed the underlying connection
+                            Trace("Unable to write to server");
+                            message.Fail(ConnectionFailureType.ProtocolFailure, null, "failure before write: " + result.ToString());
+                            message.Complete();
+                            return result;
+                        }
+                        //The parent message (next) may be returned from GetMessages
+                        //and should not be marked as sent again below
+                        messageIsSent = messageIsSent || subCommand == message;
+                    }
+                    if (!messageIsSent)
                     {
-                        // we screwed up; abort; note that WriteMessageToServer already
-                        // killed the underlying connection
-                        Trace("Unable to write to server");
-                        message.Fail(ConnectionFailureType.ProtocolFailure, null, "failure before write: " + result.ToString());
-                        message.Complete();
-                        return result;
+                        message.SetRequestSent(); // well, it was attempted, at least...
                     }
-                    //The parent message (next) may be returned from GetMessages
-                    //and should not be marked as sent again below
-                    messageIsSent = messageIsSent || subCommand == message;
+
+                    return WriteResult.Success;
                 }
-                if (!messageIsSent)
+                else
                 {
-                    message.SetRequestSent(); // well, it was attempted, at least...
+                    return WriteMessageToServerInsideWriteLock(physical, message);
                 }
-
-                return WriteResult.Success;
             }
-            else
+            finally
             {
-                return WriteMessageToServerInsideWriteLock(physical, message);
+                int endWriteTime = Environment.TickCount;
+                int writeDuration = unchecked(endWriteTime - startWriteTime);
+                if (writeDuration > _maxWriteTime)
+                {
+                    _maxWriteTime = writeDuration;
+                    _maxWriteCommand = message?.Command ?? default;
+                }
             }
         }
 
+        private volatile int _maxWriteTime = -1;
+        private RedisCommand _maxWriteCommand;
+
         [Obsolete("prefer async")]
         internal WriteResult WriteMessageTakingWriteLockSync(PhysicalConnection physical, Message message)
         {
@@ -823,7 +840,11 @@ private void ProcessBacklog()
                             _backlogStatus = BacklogStatus.RecordingTimeout;
                             var ex = Multiplexer.GetException(WriteResult.TimeoutBeforeWrite, message, ServerEndPoint);
                             ex.Data["Redis-BacklogStartDelay"] = msToStartWorker;
-                            ex.Data["Redis-BacklogGetLocDelay"] = msToGetLock;
+                            ex.Data["Redis-BacklogGetLockDelay"] = msToGetLock;
+                            if (_maxWriteTime >= 0) ex.Data["Redis-MaxWrite"] = _maxWriteTime.ToString() + ", " + _maxWriteCommand.ToString();
+                            var maxFlush = physical?.MaxFlushTime ?? -1;
+                            if (maxFlush >= 0) ex.Data["Redis-MaxFlush"] = maxFlush;
+
                             message.SetExceptionAndComplete(ex, this);
                         }
                         else

src/StackExchange.Redis/PhysicalConnection.cs

@@ -842,11 +842,12 @@ internal static int WriteRaw(Span<byte> span, long value, bool withLengthPrefix
             return WriteCrlf(span, offset);
         }
 
-        private static async ValueTask<WriteResult> FlushAsync_Awaited(PhysicalConnection connection, ValueTask<FlushResult> flush, bool throwOnFailure)
+        private async ValueTask<WriteResult> FlushAsync_Awaited(PhysicalConnection connection, ValueTask<FlushResult> flush, bool throwOnFailure, int startFlush)
         {
             try
             {
                 await flush.ForAwait();
+                RecordEndFlush(startFlush);
                 connection._writeStatus = WriteStatus.Flushed;
                 connection.UpdateLastWriteTime();
                 return WriteResult.Success;
@@ -869,7 +870,11 @@ internal WriteResult FlushSync(bool throwOnFailure, int millisecondsTimeout)
             }
             return flush.Result;
 
-            void ThrowTimeout() => throw new TimeoutException("timeout while synchronously flushing");
+            void ThrowTimeout()
+            {
+                if (millisecondsTimeout > _maxFlushTime) _maxFlushTime = millisecondsTimeout; // a fair bet even if we didn't measure
+                throw new TimeoutException("timeout while synchronously flushing");
+            }
         }
         internal ValueTask<WriteResult> FlushAsync(bool throwOnFailure)
         {
@@ -878,8 +883,10 @@ internal ValueTask<WriteResult> FlushAsync(bool throwOnFailure)
             try
             {
                 _writeStatus = WriteStatus.Flushing;
+                int startFlush = Environment.TickCount;
                 var flush = tmp.FlushAsync();
-                if (!flush.IsCompletedSuccessfully) return FlushAsync_Awaited(this, flush, throwOnFailure);
+                if (!flush.IsCompletedSuccessfully) return FlushAsync_Awaited(this, flush, throwOnFailure, startFlush);
+                RecordEndFlush(startFlush);
                 _writeStatus = WriteStatus.Flushed;
                 UpdateLastWriteTime();
                 return new ValueTask<WriteResult>(WriteResult.Success);
@@ -890,6 +897,14 @@ internal ValueTask<WriteResult> FlushAsync(bool throwOnFailure)
                 return new ValueTask<WriteResult>(WriteResult.WriteFailure);
             }
         }
+        private void RecordEndFlush(int start)
+        {
+            var end = Environment.TickCount;
+            int taken = unchecked(end - start);
+            if (taken > _maxFlushTime) _maxFlushTime = taken;
+        }
+        private volatile int _maxFlushTime = -1;
+        internal int MaxFlushTime => _maxFlushTime;
 
         private static readonly ReadOnlyMemory<byte> NullBulkString = Encoding.ASCII.GetBytes("$-1\r\n"), EmptyBulkString = Encoding.ASCII.GetBytes("$0\r\n\r\n");