Bursts of RedisTimeoutException using StackExchang

Question

I'm trying to track down intermittent "bursts" of timeouts using the StackExchange Redis library. Here's a bit about our setup: Our API is written in C# and runs on Windows 2008 and IIS. We have 4 API servers in production, and we have 4 Redis machines (Running Linux latest LTS), each with 2 instances of Redis (one master on port 7000, one slave on port 7001). I've looked at pretty much every aspect of the Redis servers and they look fantastic. No errors in the logs, CPU and network is great, everything with the server side of things seem fantastic. I can tail -f the Redis logs while this is happening and don't see anything out of the ordinary (such as rewriting AOF files or anything). I don't think the problem is with Redis.

Here's what I know so far:

• We see these timeout exceptions several times an hour. Usually between 40-50 timeouts in a minute, sometimes up to 80-90. Then, they'll go away for several minutes. There were about 5,000 of these events in the past 24 hours, and they happen in bursts from a single API client.
• These timeouts only happen against Redis master nodes, never against slave nodes. However, they happen with various Redis commands such as GETs and SETs.
• When a burst of these timeouts happen, the calls are coming from a single API server but happen talking to various Redis nodes. For example, API3 might have a bunch of timeouts trying to call Cache1, Cache2 and Cache3. This is strong evidence that the issue is related to the API servers, not the Redis servers.
• The Redis master nodes have 108 connected clients. I log current connections, and this number remains stable. There are no big spikes in connections, and it doesn't look like there's any bad code creating too many connections or not sharing ConnectionMultiplexer instances (I have one and it's static)
• The Redis slave nodes have 58 connected clients, and this also looks completely stable as well.
• We're using StackExchange.Redis version 1.2.6
• Redis is using AOF mode, and size on disk is about 195MB

Here's an example timeout exception. Most look pretty much the same as this:

Type=StackExchange.Redis.RedisTimeoutException,Message=Timeout performing GET limeade:allActivities, inst: 1, mgr: ExecuteSelect, err: never, queue: 0, qu: 0, qs: 0, qc: 0, wr: 0, wq: 0, in: 0, ar: 0, clientName: LIMEADEAPI4, serverEndpoint: 10.xx.xx.11:7000, keyHashSlot: 1295, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=9,Free=32758,Min=2,Max=32767) (Please take a look at this article for some common client-side issues that can cause timeouts: http://stackexchange.github.io/StackExchange.Redis/Timeouts),StackTrace= at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor1 processor, ServerEndPoint server) at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor1 processor, ServerEndPoint server) at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor1 processor, ServerEndPoint server) at StackExchange.Redis.RedisDatabase.StringGet(RedisKey key, CommandFlags flags) at Limeade.Caching.Providers.RedisCacheProvider1.Get[T](K cacheKey, CacheItemVersion& cacheItemVersion) in ...

I've done a bit of research on tracing down these timeout exceptions, but what's rather surprising is all the numbers are all zeros. Nothing in the queue, nothing waiting to be processed, I have tons of threads free and not doing anything. Everything looks great.

Anyone have any ideas on how to fix this? The problem is these bursts of cache timeouts cause our database to be hit more, and in certain circumstances this is a bad thing. I'm happy to add any more info that anyone would find helpful.

Update: Connection Code

The code to connect to Redis is part of a fairly complex system that supports various cache environments and configuration, but I can probably boil it down to the basics. First, there's a CacheFactory class:

public class CacheFactory : ICacheFactory
{
    private static readonly ILogger log = LoggerManager.GetLogger(typeof(CacheFactory));
    private static readonly ICacheProvider<CacheKey> cache;

    static CacheFactory()
    {
        ICacheFactory<CacheKey> configuredFactory = CacheFactorySection.Current?.CreateConfiguredFactory<CacheKey>();
        if (configuredFactory == null)
        {
           // Some error handling, not important
        }

        cache = configuredFactory.GetDefaultCache();
    }

    // ...
}

The ICacheProvider is what implements a way to talk to a certain cache system, which can be configured. In this case, the configuredFactory is a RedisCacheFactory which looks like this:

public class RedisCacheFactory<T> : ICacheFactory<T> where T : CacheKey, ICacheKeyRepository
{
    private RedisCacheProvider<T> provider;
    private readonly RedisConfiguration configuration;

    public RedisCacheFactory(RedisConfiguration config)
    {
        this.configuration = config;
    }

    public ICacheProvider<T> GetDefaultCache()
    {
        return provider ?? (provider = new RedisCacheProvider<T>(configuration));
    }
}

The GetDefaultCache method is called once, in the static constructor, and returns a RedisCacheProvider. This class is what actually connects to Redis:

public class RedisCacheProvider<K> : ICacheProvider<K> where K : CacheKey, ICacheKeyRepository
{
    private readonly ConnectionMultiplexer redisConnection;
    private readonly IDatabase db;
    private readonly RedisCacheSerializer serializer;
    private static readonly ILog log = Logging.RedisCacheProviderLog<K>();
    private readonly CacheMonitor<K> cacheMonitor;
    private readonly TimeSpan defaultTTL;
    private int connectionErrors;

    public RedisCacheProvider(RedisConfiguration options)
    {
        redisConnection = ConnectionMultiplexer.Connect(options.EnvironmentOverride ?? options.Connection);
        db = redisConnection.GetDatabase();
        serializer = new RedisCacheSerializer(options.SerializationBinding);
        cacheMonitor = new CacheMonitor<K>();
        defaultTTL = options.DefaultTTL;

        IEnumerable<string> hosts = options.Connection.EndPoints.Select(e => (e as DnsEndPoint)?.Host);
        log.InfoFormat("Created Redis ConnectionMultiplexer connection.  Hosts=({0})", String.Join(",", hosts));
    }

    // ...
 }

The constructor creates a ConnectionMultiplexer based on the configured Redis endpoints (which are in some config file). I also log every time I create a connection. We don't see any excessive number of these log statements, and the connections to Redis remains stable.

Answer 1

In global.asax, in try adding:

protected void Application_Start(object sender, EventArgs e)
{
    ThreadPool.SetMinThreads(200, 200);
}

For us, this reduced errors from ~50-100 daily to zero. I believe there is no general rule for what numbers to set as it's system dependant (200 works for us) so might require some experimenting on your end.

I also believe this has improved the performance of the site.