From 911f92c7e7ebaa789e06cba9b542a46d3a98b5a4 Mon Sep 17 00:00:00 2001 From: Kahbazi Date: Wed, 6 Nov 2019 01:28:28 +0330 Subject: [PATCH] Log heartbeat duration for slow heartbeats (#15273) --- .../Core/src/Internal/Infrastructure/Heartbeat.cs | 9 +++++++-- .../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, 19 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 7cba84b138..9cf9e2d62e 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0) { + Volatile.Write(ref _lastHeartbeatTicks, now.Ticks); + try { foreach (var callback in _callbacks) @@ -66,7 +69,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure { if (!_debugger.IsAttached) { - _trace.HeartbeatSlow(_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/IKestrelTrace.cs b/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs index f19213a07d..cd441ae3a2 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure 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 4ac7cf8ecc..1eac5326e2 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure 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)), @"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"); @@ -190,9 +190,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure _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 f0d4485b3e..bb4e896b44 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests 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 aeab28894b..bd93636c83 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 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance 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 9188ef8f22..85a7643202 100644 --- a/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs +++ b/src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs @@ -122,10 +122,10 @@ namespace Microsoft.AspNetCore.Testing _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)