huahaofeng
/
aspnetcore
1
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

Log heartbeat duration for slow heartbeats (#15273)

This commit is contained in:
Kahbazi 2019-11-06 01:28:28 +03:30 committed by Stephen Halter
parent a23dd41428
commit 911f92c7e7
6 changed files with 19 additions and 14 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

9
src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs
View File

@ -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. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System; using System;
@ -18,6 +18,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
private readonly TimeSpan _interval; private readonly TimeSpan _interval;
private Timer _timer; private Timer _timer;
private int _executingOnHeartbeat; private int _executingOnHeartbeat;
private long _lastHeartbeatTicks;
public Heartbeat(IHeartbeatHandler[] callbacks, ISystemClock systemClock, IDebugger debugger, IKestrelTrace trace) 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) if (Interlocked.Exchange(ref _executingOnHeartbeat, 1) == 0)
{ {
Volatile.Write(ref _lastHeartbeatTicks, now.Ticks);
try try
{ {
foreach (var callback in _callbacks) foreach (var callback in _callbacks)
@ -66,7 +69,9 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
{ {
if (!_debugger.IsAttached) if (!_debugger.IsAttached)
{ {
_trace.HeartbeatSlow(_interval, now); var lastHeartbeatTicks = Volatile.Read(ref _lastHeartbeatTicks);
_trace.HeartbeatSlow(TimeSpan.FromTicks(now.Ticks - lastHeartbeatTicks), _interval, now);
} }
} }
} }

2
src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs
View File

@ -39,7 +39,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
void NotAllConnectionsAborted(); void NotAllConnectionsAborted();
void HeartbeatSlow(TimeSpan interval, DateTimeOffset now); void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now);
void ApplicationNeverCompleted(string connectionId); void ApplicationNeverCompleted(string connectionId);

8
src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs
View File

@ -47,8 +47,8 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Infrastructure
private static readonly Action<ILogger, Exception> _notAllConnectionsAborted = private static readonly Action<ILogger, Exception> _notAllConnectionsAborted =
LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown."); LoggerMessage.Define(LogLevel.Debug, new EventId(21, nameof(NotAllConnectionsAborted)), "Some connections failed to abort during server shutdown.");
private static readonly Action<ILogger, TimeSpan, DateTimeOffset, Exception> _heartbeatSlow = private static readonly Action<ILogger, TimeSpan, TimeSpan, DateTimeOffset, Exception> _heartbeatSlow =
LoggerMessage.Define<TimeSpan, DateTimeOffset>(LogLevel.Warning, new EventId(22, nameof(HeartbeatSlow)), @"Heartbeat took longer than ""{interval}"" at ""{now}"". This could be caused by thread pool starvation."); LoggerMessage.Define<TimeSpan, TimeSpan, DateTimeOffset>(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<ILogger, string, Exception> _applicationNeverCompleted = private static readonly Action<ILogger, string, Exception> _applicationNeverCompleted =
LoggerMessage.Define<string>(LogLevel.Critical, new EventId(23, nameof(ApplicationNeverCompleted)), @"Connection id ""{ConnectionId}"" application never completed"); LoggerMessage.Define<string>(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); _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) public virtual void ApplicationNeverCompleted(string connectionId)

6
src/Servers/Kestrel/Core/test/HeartbeatTests.cs
View File

@ -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. // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
using System; using System;
@ -54,7 +54,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
await blockedHeartbeatTask.DefaultTimeout(); await blockedHeartbeatTask.DefaultTimeout();
heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once()); 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] [Fact]
@ -91,7 +91,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Core.Tests
await blockedHeartbeatTask.DefaultTimeout(); await blockedHeartbeatTask.DefaultTimeout();
heartbeatHandler.Verify(h => h.OnHeartbeat(systemClock.UtcNow), Times.Once()); 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] [Fact]

2
src/Servers/Kestrel/perf/Kestrel.Performance/Mocks/MockTrace.cs
View File

@ -38,7 +38,7 @@ namespace Microsoft.AspNetCore.Server.Kestrel.Performance
public void NotAllConnectionsAborted() { } public void NotAllConnectionsAborted() { }
public void NotAllConnectionsClosedGracefully() { } public void NotAllConnectionsClosedGracefully() { }
public void RequestProcessingError(string connectionId, Exception ex) { } 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 ApplicationNeverCompleted(string connectionId) { }
public void RequestBodyStart(string connectionId, string traceIdentifier) { } public void RequestBodyStart(string connectionId, string traceIdentifier) { }
public void RequestBodyDone(string connectionId, string traceIdentifier) { } public void RequestBodyDone(string connectionId, string traceIdentifier) { }

6
src/Servers/Kestrel/shared/test/CompositeKestrelTrace.cs
View File

@ -122,10 +122,10 @@ namespace Microsoft.AspNetCore.Testing
_trace2.NotAllConnectionsAborted(); _trace2.NotAllConnectionsAborted();
} }
public void HeartbeatSlow(TimeSpan interval, DateTimeOffset now) public void HeartbeatSlow(TimeSpan heartbeatDuration, TimeSpan interval, DateTimeOffset now)
{ {
_trace1.HeartbeatSlow(interval, now); _trace1.HeartbeatSlow(heartbeatDuration, interval, now);
_trace2.HeartbeatSlow(interval, now); _trace2.HeartbeatSlow(heartbeatDuration, interval, now);
} }
public void ApplicationNeverCompleted(string connectionId) public void ApplicationNeverCompleted(string connectionId)