Use a dedicated thread for timers in rather than a Timer (#21490)

* Use a dedicated thread for timers in rather than a Timer
- This make it possible to still timeout various operations when there's thread pool starvation occurring.
- Print heartbeat slow if duration > interval

Author: davidfowl

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

@@ -16,9 +16,8 @@ internal class Heartbeat : IDisposable
         private readonly IDebugger _debugger;
         private readonly IKestrelTrace _trace;
         private readonly TimeSpan _interval;
-        private Timer _timer;
-        private int _executingOnHeartbeat;
-        private long _lastHeartbeatTicks;
+        private Thread _timerThread;
+        private volatile bool _stopped;
 
         public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace)
         {
@@ -27,58 +26,62 @@ public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebug
             _debugger = debugger;
             _trace = trace;
             _interval = Interval;
+            _timerThread = new Thread(state => ((Heartbeat)state).TimerLoop())
+            {
+                Name = "Kestrel Timer",
+                IsBackground = true
+            };
         }
 
         public void Start()
         {
             OnHeartbeat();
-            _timer = new Timer(OnHeartbeat, state: this, dueTime: _interval, period: _interval);
-        }
-
-        private static void OnHeartbeat(object state)
-        {
-            ((Heartbeat)state).OnHeartbeat();
+            _timerThread.Start(this);
         }
 
-        // Called by the Timer (background) thread
         internal void OnHeartbeat()
         {
             var now = _systemClock.UtcNow;
 
-            if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0)
+            try
             {
-                Volatile.Write(ref _lastHeartbeatTicks, now.Ticks);
+                foreach (var callback in _callbacks)
+                {
+                    callback.OnHeartbeat(now);
+                }
 
-                try
+                if (!_debugger.IsAttached)
                 {
-                    foreach (var callback in _callbacks)
+                    var after = _systemClock.UtcNow;
+
+                    var duration = TimeSpan.FromTicks(after.Ticks - now.Ticks);
+
+                    if (duration > _interval)
                     {
-                        callback.OnHeartbeat(now);
+                        _trace.HeartbeatSlow(duration, _interval, now);
                     }
                 }
-                catch (Exception ex)
-                {
-                    _trace.LogError(0, ex, $"{nameof(Heartbeat)}.{nameof(OnHeartbeat)}");
-                }
-                finally
-                {
-                    Interlocked.Exchange(ref _executingOnHeartbeat, 0);
-                }
             }
-            else
+            catch (Exception ex)
             {
-                if (!_debugger.IsAttached)
-                {
-                    var lastHeartbeatTicks = Volatile.Read(ref _lastHeartbeatTicks);
-                    
-                    _trace.HeartbeatSlow(TimeSpan.FromTicks(now.Ticks - lastHeartbeatTicks), _interval, now);
-                }
+                _trace.LogError(0, ex, $"{nameof(Heartbeat)}.{nameof(OnHeartbeat)}");
+            }
+        }
+
+        private void TimerLoop()
+        {
+            while (!_stopped)
+            {
+                Thread.Sleep(_interval);
+
+                OnHeartbeat();
             }
         }
 
         public void Dispose()
         {
-            _timer?.Dispose();
+            _stopped = true;
+            // Don't block waiting for the thread to exit
         }
     }
 }

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

@@ -85,7 +85,7 @@ public void GetDateHeaderValue_ReturnsUpdatedValueAfterHeartbeat()
                 heartbeat.OnHeartbeat();
 
                 Assert.Equal(future.ToString(Rfc1123DateFormat), dateHeaderValueManager.GetDateHeaderValues().String);
-                Assert.Equal(2, systemClock.UtcNowCalled);
+                Assert.Equal(4, systemClock.UtcNowCalled);
             }
         }
 

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

@@ -22,16 +22,17 @@ public void HeartbeatIntervalIsOneSecond()
         }
 
         [Fact]
-        public async Task BlockedHeartbeatDoesntCauseOverlapsAndIsLoggedAsError()
+        public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError()
         {
             var systemClock = new MockSystemClock();
             var heartbeatHandler = new Mock<IHeartbeatHandler>();
             var debugger = new Mock<IDebugger>();
             var kestrelTrace = new Mock<IKestrelTrace>();
             var handlerMre = new ManualResetEventSlim();
             var handlerStartedTcs = new TaskCompletionSource<object>(TaskCreationOptions.RunContinuationsAsynchronously);
+            var now = systemClock.UtcNow;
 
-            heartbeatHandler.Setup(h => h.OnHeartbeat(systemClock.UtcNow)).Callback(() =>
+            heartbeatHandler.Setup(h => h.OnHeartbeat(now)).Callback(() =>
             {
                 handlerStartedTcs.SetResult(null);
                 handlerMre.Wait();
@@ -45,29 +46,31 @@ public async Task BlockedHeartbeatDoesntCauseOverlapsAndIsLoggedAsError()
                 blockedHeartbeatTask = Task.Run(() => heartbeat.OnHeartbeat());
 
                 await handlerStartedTcs.Task.DefaultTimeout();
-
-                heartbeat.OnHeartbeat();
             }
 
+            // 2 seconds passes...
+            systemClock.UtcNow = systemClock.UtcNow.AddSeconds(2);
+
             handlerMre.Set();
 
             await blockedHeartbeatTask.DefaultTimeout();
 
-            heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once());
-            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.Zero, Heartbeat.Interval, systemClock.UtcNow), Times.Once());
+            heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once());
+            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.FromSeconds(2), Heartbeat.Interval, now), Times.Once());
         }
 
         [Fact]
-        public async Task BlockedHeartbeatIsNotLoggedAsErrorIfDebuggerAttached()
+        public async Task HeartbeatTakingLongerThanIntervalIsNotLoggedAsErrorIfDebuggerAttached()
         {
             var systemClock = new MockSystemClock();
             var heartbeatHandler = new Mock<IHeartbeatHandler>();
             var debugger = new Mock<IDebugger>();
             var kestrelTrace = new Mock<IKestrelTrace>();
             var handlerMre = new ManualResetEventSlim();
             var handlerStartedTcs = new TaskCompletionSource<object>(TaskCreationOptions.RunContinuationsAsynchronously);
+            var now = systemClock.UtcNow;
 
-            heartbeatHandler.Setup(h => h.OnHeartbeat(systemClock.UtcNow)).Callback(() =>
+            heartbeatHandler.Setup(h => h.OnHeartbeat(now)).Callback(() =>
             {
                 handlerStartedTcs.SetResult(null);
                 handlerMre.Wait();
@@ -82,16 +85,17 @@ public async Task BlockedHeartbeatIsNotLoggedAsErrorIfDebuggerAttached()
                 blockedHeartbeatTask = Task.Run(() => heartbeat.OnHeartbeat());
 
                 await handlerStartedTcs.Task.DefaultTimeout();
-
-                heartbeat.OnHeartbeat();
             }
 
+            // 2 seconds passes...
+            systemClock.UtcNow = systemClock.UtcNow.AddSeconds(2);
+
             handlerMre.Set();
 
             await blockedHeartbeatTask.DefaultTimeout();
 
-            heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once());
-            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.Zero, Heartbeat.Interval, systemClock.UtcNow), Times.Never());
+            heartbeatHandler.Verify(h => h.OnHeartbeat(now), Times.Once());
+            kestrelTrace.Verify(t => t.HeartbeatSlow(TimeSpan.FromSeconds(2), Heartbeat.Interval, now), Times.Never());
         }
 
         [Fact]