From ec55f8703847b79abf4f8ad8fadcf0a6bfa47edf Mon Sep 17 00:00:00 2001 From: Kahbazi Date: Tue, 22 Oct 2019 22:44:30 +0330 Subject: [PATCH 1/2] Log heartbeat duration for slow heartbeats --- .../Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs | 6 ++++-- .../Core/src/Internal/Infrastructure/IKestrelTrace.cs | 2 +- .../Core/src/Internal/Infrastructure/KestrelTrace.cs | 8 ++++---- src/Servers/Kestrel/Core/test/HeartbeatTests.cs | 6 +++--- .../Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs | 2 +- src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs | 6 +++--- 6 files changed, 16 insertions(+), 14 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index 7cba84b13884..aa3501789df3 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/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 DateTimeOffset _lastHeartbeat; public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) { @@ -46,6 +47,7 @@ internal void OnHeartbeat() if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0) { + _lastHeartbeat = now; try { foreach (var callback in _callbacks) @@ -66,7 +68,7 @@ internal void OnHeartbeat() { if (!_debugger.IsAttached) { - _trace.HeartbeatSlow(_interval, now); + _trace.HeartbeatSlow(now - _lastHeartbeat, _interval, now); } } } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs index 1a5815300e24..d5454a6069f9 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs +++ b/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); diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index d72aa3c707dc..5a6c7f319955 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -47,8 +47,8 @@ internal class KestrelTrace : IKestrelTrace private static readonly Action _notAllConnectionsAborted = LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown."); - private static readonly Action _heartbeatSlow = - LoggerMessage.Define(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 _heartbeatSlow = + LoggerMessage.Define(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"Heartbeat took ""{heartbeatDuration}"" which is longer than ""{interval}"" at ""{now}"". This could be caused by thread pool starvation."); private static readonly Action _applicationNeverCompleted = LoggerMessage.Define(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) diff --git a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs b/src/Servers/Kestrel/Core/test/HeartbeatTests.cs index f0d4485b3ee8..bb4e896b44b7 100644 --- a/src/Servers/Kestrel/Core/test/HeartbeatTests.cs +++ b/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] diff --git a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs index d2514f998f39..770b5d099b11 100644 --- a/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs +++ b/src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs @@ -38,7 +38,7 @@ public void Log(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) { } diff --git a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs index f4b55a18a6eb..220929caea56 100644 --- a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs +++ b/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) From afdf9b2af432c18b4ca177a10990bab81b1ffad0 Mon Sep 17 00:00:00 2001 From: Kahbazi Date: Wed, 23 Oct 2019 05:17:54 +0330 Subject: [PATCH 2/2] Volatile read and write for last heartbeat --- .../Core/src/Internal/Infrastructure/Heartbeat.cs | 9 ++++++--- .../Core/src/Internal/Infrastructure/KestrelTrace.cs | 2 +- 2 files changed, 7 insertions(+), 4 deletions(-) diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs index aa3501789df3..9cf9e2d62e35 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs @@ -18,7 +18,7 @@ internal class Heartbeat : IDisposable private readonly TimeSpan _interval; private Timer _timer; private int _executingOnHeartbeat; - private DateTimeOffset _lastHeartbeat; + private long _lastHeartbeatTicks; public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) { @@ -47,7 +47,8 @@ internal void OnHeartbeat() if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0) { - _lastHeartbeat = now; + Volatile.Write(ref _lastHeartbeatTicks, now.Ticks); + try { foreach (var callback in _callbacks) @@ -68,7 +69,9 @@ internal void OnHeartbeat() { if (!_debugger.IsAttached) { - _trace.HeartbeatSlow(now - _lastHeartbeat, _interval, now); + var lastHeartbeatTicks = Volatile.Read(ref _lastHeartbeatTicks); + + _trace.HeartbeatSlow(TimeSpan.FromTicks(now.Ticks - lastHeartbeatTicks), _interval, now); } } } diff --git a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs index 5a6c7f319955..27af4870b48c 100644 --- a/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs +++ b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs @@ -48,7 +48,7 @@ internal class KestrelTrace : IKestrelTrace LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown."); private static readonly Action _heartbeatSlow = - LoggerMessage.Define(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"Heartbeat took ""{heartbeatDuration}"" which is longer than ""{interval}"" at ""{now}"". This could be caused by thread pool starvation."); + LoggerMessage.Define(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 _applicationNeverCompleted = LoggerMessage.Define(LogLevel.Critical, new EventId(23, nameof(ApplicationNeverCompleted)), @"Connection id ""{ConnectionId}"" application never completed");