HeartbeatSlow warning missing context

[benaadams]

The warning outputs

Heartbeat took longer than 00:00:01 at 31/07/2019 14:14:00.
This could be caused by thread pool starvation.

It would be good it it included in the message how long it took, rather than just the threshold.

e.g. was it 1ms over, 1sec over, 1min over, 1hr over etc; they are all very different magnitudes

/cc @halter73

[analogrelay]

Sounds like a good idea. We wouldn't be able to go below 1s of precision though since we're using the cached system clock that has a maximum precision of 1s.

[analogrelay]

Basically just a matter of comparing now against _systemClock.UtcNow again before emitting the heartbeat slow event in https://github.com/aspnet/AspNetCore/blob/060d35cd04db1ce06dc816a8ec0faf9fd88d7a29/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs#L43

[zHaytam]

Hello, I would like to take this issue as my first, if possible.
I have one question though, shouldn't the methods' definitions change for them to accept another argument, which represents the duration (how long it took)?

Methods that I found:

• https://github.com/aspnet/AspNetCore/blob/9851e0168812471e52c4c965a0c0005240f762ba/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs#L193
• https://github.com/aspnet/AspNetCore/blob/9851e0168812471e52c4c965a0c0005240f762ba/src/Servers/Kestrel/Core/src/Internal/Infrastructure/KestrelTrace.cs#L50
• https://github.com/aspnet/AspNetCore/blob/9851e0168812471e52c4c965a0c0005240f762ba/src/Servers/Kestrel/Core/src/Internal/Infrastructure/IKestrelTrace.cs#L42

[halter73]

That @zHaytam. I agree that it makes sense change the signature of the (I)KestrelTrace.HeartBeatSlow methods and Action to take another argument representing duration. I'd probably make the argument a TimeSpan but just print out TimeSpan.TotalSeconds in the log message.

[zHaytam]

I have another question:
If this is a timer that runs every _interval, and in every run checks if the method in use:

• Not used: heartbeat is performed normally.
• Used: HeartbeatSlow event is emitted

Then wouldn't calculating the difference between now and _systemClock.UtcNow would not represent the duration, since its the last heartbeat who hold the method for too long.

[zHaytam]

After thinking about it some more, if the timer runs every _interval and the next heartbeat checks if the last heartbeat isn't done yet, then the duration will always equal the interval no?

Maybe we could add another event inside the finally block where it's fired if the difference between _systemClock.UtcNow and now was greater than _interval, which should give us a
meaningful duration.

https://github.com/aspnet/AspNetCore/blob/060d35cd04db1ce06dc816a8ec0faf9fd88d7a29/src/Servers/Kestrel/Core/src/Internal/Infrastructure/Heartbeat.cs#L62