Small timeouts: Time elapsed is much greater than timeout

[tyzoid]

When a timeout of 100ms is set, it appears that StackExchange.Redis takes upwards of 1000ms to actually time out. I would expect that this would time out much closer to the 100ms limit that's set in the configuration.

StackExchange.Redis.RedisTimeoutException :: StackExchange.Redis.RedisTimeoutException: Timeout awaiting response (outbound=0KiB, inbound=0KiB, 922ms elapsed, timeout is 100ms), command=GET, next: GET XXXXXXXXXX, inst: 0, qu: 20, qs: 1362, aw: True, bw: WritingMessage, rs: ReadAsync, ws: Writing, in: 0, in-pipe: 0, out-pipe: 0, serverEndpoint: XXX.XXX.XXX.XXX:6379, mc: 1/1/0, mgr: 9 of 10 available, clientName: XXXXX(SE.Redis-v2.5.61.22961), IOCP: (Busy=2,Free=998,Min=8,Max=1000), WORKER: (Busy=12,Free=8179,Min=8,Max=8191), v: 2.5.61.22961 (Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts)
       at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
       at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
       at XXXX<Application Code>

Here's the configuration we're supplying:

ConfigurationOptions options = new ConfigurationOptions
{
	Password = password,
	Ssl = false,
	AbortOnConnectFail = false,
	SyncTimeout = 100,
	AsyncTimeout = 100,
	ReconnectRetryPolicy = new LinearRetry(200),
	BacklogPolicy = BacklogPolicy.FailFast
};

[NickCraver]

The timeout is only evaluated on the heartbeat interval (every 1000ms), so if you set it far lower it may be anywhere from 100ms -> ~1000ms (depending on system timers) when it triggers. Basically: once a second, we crawl the queue and check for violators. This is a global tradeoff between fidelity and paying a high overhead for timeout evaluation, and currently intentional.

[tyzoid]

Ok. Would it be feasible to have a flag added to enable a higher-precision timer to evaluate timeouts? If not (and the feature request does not want to be entertained), feel free to close as designed.

[NickCraver]

There are no plans currently because it's a bigger change that that affecting the heartbeat in general, but it may be something that gets easier later. Adding to @mgravell's radar as some of this may shift with the blocking commands work happening.

[tyzoid]

Just to illustrate our use case, we have a high-performance service with a very low latency SLA of 300ms. If everything is working normally, it's fine, but if we disconnect one of the redis instances from the pool suddenly, we want to perform a very fast retry on another server to avoid service disruptions. We've got 4-6 secondary redis instances in the pool at any given time. The data blobs we're pulling from redis are usually around 500 bytes or so.

[NickCraver]

Update here: After getting into it and a few other use cases/trade-offs, I think adjusting the heartbeat if you're okay with the extra overhead that adds is something I want to allow. Fired up a proposal in #2243 for others to look at and weigh in on.