From d41ab9a77c46d75e13e99fc44d345a774a1bd4fc Mon Sep 17 00:00:00 2001 From: David Fowler Date: Mon, 4 May 2020 23:24:49 -0700 Subject: [PATCH 1/4] 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 occuring. - One downside is that the heartbeatslow warning that usually can communicate starvation to users is now gone. --- .../src/Internal/Infrastructure/Heartbeat.cs | 62 +++++++++---------- 1 file changed, 29 insertions(+), 33 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index 9cf9e2d62e35..34471b8d8d0e 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs @@ -16,9 +16,9 @@ internal class Heartbeat : IDisposable private readonly IDebugger _debugger; private readonly IKestrelTrace _trace; private readonly TimeSpan _interval; - private Timer _timer; - private int _executingOnHeartbeat; + private Thread _timerThread; private long _lastHeartbeatTicks; + private volatile bool _stopped; public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) { @@ -27,58 +27,54 @@ 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); + _timerThread.Start(this); } - private static void OnHeartbeat(object state) - { - ((Heartbeat)state).OnHeartbeat(); - } - - // Called by the Timer (background) thread internal void OnHeartbeat() { var now = _systemClock.UtcNow; - if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0) - { - Volatile.Write(ref _lastHeartbeatTicks, now.Ticks); + Volatile.Write(ref _lastHeartbeatTicks, now.Ticks); - try - { - foreach (var callback in _callbacks) - { - callback.OnHeartbeat(now); - } - } - catch (Exception ex) - { - _trace.LogError(0, ex, $"{nameof(Heartbeat)}.{nameof(OnHeartbeat)}"); - } - finally + try + { + foreach (var callback in _callbacks) { - Interlocked.Exchange(ref _executingOnHeartbeat, 0); + callback.OnHeartbeat(now); } } - 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)}"); + } + + Thread.Sleep(_interval); + } + + private void TimerLoop() + { + while (!_stopped) + { + OnHeartbeat(); + + Thread.Sleep(_interval); } } public void Dispose() { - _timer?.Dispose(); + _stopped = true; + // Don't block waiting for the thread to exit } } } From f935292d4940a87471194e523b21943e7c2ebd53 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Tue, 5 May 2020 00:41:58 -0700 Subject: [PATCH 2/4] Apply suggestions from code review MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Günther Foidl --- .../Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index 34471b8d8d0e..1e6c7c9760be 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs @@ -58,7 +58,6 @@ internal void OnHeartbeat() _trace.LogError(0, ex, $"{nameof(Heartbeat)}.{nameof(OnHeartbeat)}"); } - Thread.Sleep(_interval); } private void TimerLoop() From f7148d2f0126a9574e98cf8771e533770b2dc08f Mon Sep 17 00:00:00 2001 From: David Fowler Date: Tue, 5 May 2020 23:20:06 -0700 Subject: [PATCH 3/4] PR feedback - Print heartbeat slow if duration > interval - Fix tests --- .../src/Internal/Infrastructure/Heartbeat.cs | 20 +++++++++---- .../Kestrel/Core/test/HeartbeatTests.cs | 28 +++++++++++-------- 2 files changed, 30 insertions(+), 18 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index 1e6c7c9760be..e26a2961cbba 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs @@ -17,7 +17,6 @@ internal class Heartbeat : IDisposable private readonly IKestrelTrace _trace; private readonly TimeSpan _interval; private Thread _timerThread; - private long _lastHeartbeatTicks; private volatile bool _stopped; public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) @@ -44,29 +43,38 @@ internal void OnHeartbeat() { var now = _systemClock.UtcNow; - Volatile.Write(ref _lastHeartbeatTicks, now.Ticks); - try { foreach (var callback in _callbacks) { callback.OnHeartbeat(now); } + + if (!_debugger.IsAttached) + { + var after = _systemClock.UtcNow; + + var duration = TimeSpan.FromTicks(after.Ticks - now.Ticks); + + if (duration > _interval) + { + _trace.HeartbeatSlow(duration, _interval, now); + } + } } catch (Exception ex) { _trace.LogError(0, ex, $"{nameof(Heartbeat)}.{nameof(OnHeartbeat)}"); } - } private void TimerLoop() { while (!_stopped) { - OnHeartbeat(); - Thread.Sleep(_interval); + + OnHeartbeat(); } } diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index bb4e896b44b7..680fa6af8b64 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs @@ -22,7 +22,7 @@ public void HeartbeatIntervalIsOneSecond() } [Fact] - public async Task BlockedHeartbeatDoesntCauseOverlapsAndIsLoggedAsError() + public async Task HeartbeatTakingLongerThanIntervalIsLoggedAsError() { var systemClock = new MockSystemClock(); var heartbeatHandler = new Mock(); @@ -30,8 +30,9 @@ public async Task BlockedHeartbeatDoesntCauseOverlapsAndIsLoggedAsError() var kestrelTrace = new Mock(); var handlerMre = new ManualResetEventSlim(); var handlerStartedTcs = new TaskCompletionSource(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,20 +46,21 @@ 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(); @@ -66,8 +68,9 @@ public async Task BlockedHeartbeatIsNotLoggedAsErrorIfDebuggerAttached() var kestrelTrace = new Mock(); var handlerMre = new ManualResetEventSlim(); var handlerStartedTcs = new TaskCompletionSource(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] From b471fe866d7c3f26c350614a4db339a7ccb1d168 Mon Sep 17 00:00:00 2001 From: David Fowler Date: Wed, 6 May 2020 18:23:04 -0700 Subject: [PATCH 4/4] Fix another test --- src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs b/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs index 4e5d76b15673..ec393bd688b6 100644 --- a/src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs +++ b/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); } }