Let's have a class that every 5 seconds refreshes a key in Redis. (We call it "dead man switch"). The problem is, once per several days it just stops emitting the Elapsed event for a brief period of time, from seconds to 1-2 minutes.
using System;
using System.Timers;
using Microsoft.Extensions.Logging;
using StackExchange.Redis;
namespace My
{
public class Test : IDisposable
{
private readonly ILogger<Test> _logger;
private readonly IDatabase _redis;
private readonly System.Timers.Timer _timer;
public Test(ILogger<Test> logger, IDatabase redis)
{
_logger = logger;
_redis = redis;
_timer = new Timer {Interval = 5000};
_timer.Elapsed += Beat;
_timer.Start();
}
private void Beat(object sender, ElapsedEventArgs e)
{
_logger.LogInformation("Pushing DMS.");
_redis.StringSet("1234", "OK", TimeSpan.FromSeconds(10), When.Always, CommandFlags.FireAndForget);
_logger.LogInformation("DMS Pushed.");
}
public void Dispose()
{
Console.WriteLine("Disposing.");
_timer?.Dispose();
}
}
}
Log:
...
[08:08:40 INF] Pushing DMS.
[08:08:40 INF] DMS pushed.
[08:08:45 INF] Pushing DMS.
[08:08:45 INF] DMS pushed.
[08:08:50 INF] Pushing DMS.
[08:08:50 INF] DMS pushed.
[08:09:17 INF] Pushing DMS. #<-- Here's a 27s gap
[08:08:17 INF] DMS pushed.
[08:08:23 INF] Pushing DMS.
[08:08:23 INF] DMS pushed.
...
These events do not queue up - it just creates a gap. This class is a part of bigger project running in a kubernetes cluster.
I've googled up a theory that it can be caused by threadpool starvation so I added debug logging of threadpool state, but it IMO does not bring up any relevant information:
private void Beat(object sender, ElapsedEventArgs e)
{
var ptc = Process.GetCurrentProcess().Threads.Count;
ThreadPool.GetMaxThreads(out var maxWt, out var maxCpt);
ThreadPool.GetAvailableThreads(out var wt, out var cpt);
var current = ThreadPool.ThreadCount;
var pending = ThreadPool.PendingWorkItemCount;
var threadId = Thread.CurrentThread.ManagedThreadId;
_logger.LogDebug(
$"Pushing DMS.\nTP state: Thread#: {threadId} \t#Current: {current}\t #Pending: {pending}\t#WorkerT: {wt}/{maxWt}\t #CompletionT: {cpt}/{maxCpt}\n#ProcessT: {ptc}");
_redis.StringSet("1234", "OK", TimeSpan.FromSeconds(5), When.Always, CommandFlags.FireAndForget);
_logger.LogInformation("DMS Pushed.");
}
Resulting log:
[02:31:13 INF] Pushing DMS.
TP state: Thread#: 92 #Current: 8 #Pending: 0 #WorkerT: 32760/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:31:13 INF] DMS Pushed.
[02:31:18 INF] Pushing DMS.
TP state: Thread#: 47 #Current: 11 #Pending: 0 #WorkerT: 32760/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:31:18 INF] DMS Pushed.
[02:31:23 INF] Pushing DMS.
TP state: Thread#: 47 #Current: 11 #Pending: 0 #WorkerT: 32761/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:31:23 INF] DMS Pushed.
[02:31:28 INF] Pushing DMS.
TP state: Thread#: 92 #Current: 8 #Pending: 0 #WorkerT: 32760/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:31:28 INF] DMS Pushed.
# HERE COMES THE GAP
[02:33:01 INF] Pushing DMS.
TP state: Thread#: 103 #Current: 8 #Pending: 0 #WorkerT: 32760/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:33:01 INF] DMS Pushed.
[02:33:06 INF] Pushing DMS.
TP state: Thread#: 55 #Current: 10 #Pending: 0 #WorkerT: 32762/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:33:06 INF] DMS Pushed.
[02:33:11 INF] Pushing DMS.
TP state: Thread#: 103 #Current: 10 #Pending: 0 #WorkerT: 32762/32767 #CompletionT: 1000/1000
#ProcessT: 46
[02:33:11 INF] DMS Pushed.
Does anyone have an idea what can cause this behavior?