Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
May 8, 2020
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
d41ab9a
Use a dedicated thread for timers in rather than a Timer
davidfowl May 5, 2020
f935292
Apply suggestions from code review
davidfowl May 5, 2020
f7148d2
PR feedback
davidfowl May 6, 2020
b471fe8
Fix another test
davidfowl May 7, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 34 additions & 31 deletions src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand All @@ -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
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

In LibuvThread, we set IsBackground to false in debug so we can find issues where the thread isn't properly stopping.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure but the libuv thread does more than this. I wouldn’t compare the 2. We could set it to true in debug if you’re paranoid about the timer not shutting down.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How/when does this get initiated? Is it lazy and triggered by a first request? i.e. does it need executioncontext flow supression?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Don't want an HttpContext stuck hanging around on a Thread 😉

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How/when does this get initiated? Is it lazy and triggered by a first request? i.e. does it need executioncontext flow supression?

Startup. Could suppress execution context but that isn't new behavior. The Timer before didn't suppress it 😄 , nothing new here.

};
}

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;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not implement DisposeAsync and wait? Maybe throw after a timeout.

Copy link
Member Author

@davidfowl davidfowl May 5, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Because it’s not important. Any hung thread will be visible in the debugger/dump.

// Don't block waiting for the thread to exit
}
}
}
2 changes: 1 addition & 1 deletion src/Servers/Kestrel/Core/test/DateHeaderValueManagerTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}

Expand Down
28 changes: 16 additions & 12 deletions src/Servers/Kestrel/Core/test/HeartbeatTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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();
Expand All @@ -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();
Expand All @@ -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]
Expand Down