Log heartbeat duration for slow heartbeats (#15273)

Author: Kahbazi

src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs

@@ -1,4 +1,4 @@
-// Copyright (c) .NET Foundation. All rights reserved.
+// Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
@@ -18,6 +18,7 @@ internal class Heartbeat : IDisposable
         private readonly TimeSpan _interval;
         private Timer _timer;
         private int _executingOnHeartbeat;
+        private long _lastHeartbeatTicks;
 
         public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace)
         {
@@ -46,6 +47,8 @@ internal void OnHeartbeat()
 
             if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0)
             {
+                Volatile.Write(ref _lastHeartbeatTicks, now.Ticks);
+
                 try
                 {
                     foreach (var callback in _callbacks)
@@ -66,7 +69,9 @@ internal void OnHeartbeat()
             {
                 if (!_debugger.IsAttached)
                 {
-                    _trace.HeartbeatSlow(_interval, now);
+                    var lastHeartbeatTicks = Volatile.Read(ref _lastHeartbeatTicks);
+                    
+                    _trace.HeartbeatSlow(TimeSpan.FromTicks(now.Ticks - lastHeartbeatTicks), _interval, now);
                 }
             }
         }

src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs

@@ -39,7 +39,7 @@ internal interface IKestrelTrace : ILogger
 
         void NotAllConnectionsAborted();
 
-        void HeartbeatSlow(TimeSpan interval, DateTimeOffset now);
+        void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now);
 
         void ApplicationNeverCompleted(string connectionId);
 

src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs

@@ -47,8 +47,8 @@ internal class KestrelTrace : IKestrelTrace
         private static readonly Action<ILogger, Exception> _notAllConnectionsAborted =
             LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown.");
 
-        private static readonly Action<ILogger, TimeSpan, DateTimeOffset, Exception> _heartbeatSlow =
-            LoggerMessage.Define<TimeSpan, DateTimeOffset>(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"Heartbeat took longer than ""{interval}"" at ""{now}"". This could be caused by thread pool starvation.");
+        private static readonly Action<ILogger, TimeSpan, TimeSpan, DateTimeOffset, Exception> _heartbeatSlow =
+            LoggerMessage.Define<TimeSpan, TimeSpan, DateTimeOffset>(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"As of ""{now}"", the heartbeat has been running for ""{heartbeatDuration}"" which is longer than ""{interval}"". This could be caused by thread pool starvation.");
 
         private static readonly Action<ILogger, string, Exception> _applicationNeverCompleted =
             LoggerMessage.Define<string>(LogLevel.Critical, new EventId(23, nameof(ApplicationNeverCompleted)), @"Connection id ""{ConnectionId}"" application never completed");
@@ -190,9 +190,9 @@ public virtual void NotAllConnectionsAborted()
             _notAllConnectionsAborted(_logger, null);
         }
 
-        public virtual void HeartbeatSlow(TimeSpan interval, DateTimeOffset now)
+        public virtual void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now)
         {
-            _heartbeatSlow(_logger, interval, now, null);
+            _heartbeatSlow(_logger, heartbeatDuration, interval, now, null);
         }
 
         public virtual void ApplicationNeverCompleted(string connectionId)

src/Servers/Kestrel/Core/test/HeartbeatTests.cs

@@ -1,4 +1,4 @@
-// Copyright (c) .NET Foundation. All rights reserved.
+// Copyright (c) .NET Foundation. All rights reserved.
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System;
@@ -54,7 +54,7 @@ public async Task BlockedHeartbeatDoesntCauseOverlapsAndIsLoggedAsError()
             await blockedHeartbeatTask.DefaultTimeout();
 
             heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once());
-            kestrelTrace.Verify(t => t.HeartbeatSlow(Heartbeat.Interval, systemClock.UtcNow), Times.Once());
+            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.Zero, Heartbeat.Interval, systemClock.UtcNow), Times.Once());
         }
 
         [Fact]
@@ -91,7 +91,7 @@ public async Task BlockedHeartbeatIsNotLoggedAsErrorIfDebuggerAttached()
             await blockedHeartbeatTask.DefaultTimeout();
 
             heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once());
-            kestrelTrace.Verify(t => t.HeartbeatSlow(Heartbeat.Interval, systemClock.UtcNow), Times.Never());
+            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.Zero, Heartbeat.Interval, systemClock.UtcNow), Times.Never());
         }
 
         [Fact]

src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs

@@ -38,7 +38,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
         public void NotAllConnectionsAborted() { }
         public void NotAllConnectionsClosedGracefully() { }
         public void RequestProcessingError(string connectionId, Exception ex) { }
-        public void HeartbeatSlow(TimeSpan interval, DateTimeOffset now) { }
+        public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now) { }
         public void ApplicationNeverCompleted(string connectionId) { }
         public void RequestBodyStart(string connectionId, string traceIdentifier) { }
         public void RequestBodyDone(string connectionId, string traceIdentifier) { }

src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs

@@ -122,10 +122,10 @@ public void NotAllConnectionsAborted()
             _trace2.NotAllConnectionsAborted();
         }
 
-        public void HeartbeatSlow(TimeSpan interval, DateTimeOffset now)
+        public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now)
         {
-            _trace1.HeartbeatSlow(interval, now);
-            _trace2.HeartbeatSlow(interval, now);
+            _trace1.HeartbeatSlow(heartbeatDuration, interval, now);
+            _trace2.HeartbeatSlow(heartbeatDuration, interval, now);
         }
 
         public void ApplicationNeverCompleted(string connectionId)