StackExchange.Redis Timeout performing 超时问题

最近在做的一个项目，用的.net core 2.1,然后缓存用的Redis，缓存相关封装是同事写的，用的驱动是StackExchange.Redis version 2.0.571 ，一直听说这个驱动并发情况下有TimeOut bug，项目开发差不多后，我压测了一下，简单的模拟30个用户持续访问某一个有用到缓存的查询接口，结果这么小的压力下超时异常出现：

Timeout performing GET my_141 (5000ms), inst: 30, qu: 0, qs: 20, in: 20320, serverEndpoint: 172.16.3.119:6379, mgr: 10 of 10 available, clientName: s-119, IOCP: (Busy=0,Free=1000,Min=1,Max=1000), WORKER: (Busy=120,Free=32747,Min=1,Max=32767), v: 2.0.571.20511(Please take a look at this article for some common client-side issues that can cause timeouts: https://stackexchange.github.io/StackExchange.Redis/Timeouts))

后面是堆栈信息…

蛋疼了很久，搜了很多文章，得到以下

解决方案

1、换掉，不用这个驱动（ 可以看看.net core redis 驱动推荐，为什么不使用 StackExchange.Redis）

2、redis操作修改为全部异步&& ThreadPool.SetMinThreads(200, 200);

我用的第二种解决了问题，主要换驱动也可能遇到坑；还有时间成本问题；

原因简析

我们看到以上的异常信息当中有这么一段：

IOCP: (Busy=0,Free=1000,Min=1,Max=1000),

WORKER: (Busy=120,Free=32747,Min=1,Max=32767),

意思是当前繁忙的WORKER 线程有120个，而系统“要由线程池根据需要创建的新的最小工作程序线程数。”，也就是系统创建的工作线程数不足以满足redis的Get操作的繁忙线程的需求，导致部分Get操作的线程堵塞超时了；

所以我们把“最小线程workerThreads” 修改为200解决问题；

200是我估摸着生产环境服务器设置的，该值设置不合理有可能导致性能问题；

---

StackExchange.Redis超时的问题

最近公司有个项目，在请求量大的情况下，有大量的错误日志是关于redis超时的问题：

Timeout performing SET XXX, inst: 27, mgr: ProcessReadQueue, err: never, queue: 3, qu: 0, qs: 3, qc: 0, wr: 0, wq: 0, in: 15, ar: 1, clientName: XXX, serverEndpoint: 192.168.x.x:6379, keyHashSlot: 944, IOCP: (Busy=0,Free=1000,Min=4,Max=1000), WORKER: (Busy=4,Free=4091,Min=4,Max=4095) (Please take a look at this article for some common client-side issues that can cause timeouts: http://stackexchange.github.io/StackExchange.Redis/Timeouts)

在网上找解决方案，有说是redis服务端设置的内存不够，客户端连接超时时间设置的长一点，同步时间设置长一点。最后都没有用，只是定位到了是客户端的问题，和服务端没问题。然后继续找在网上发现

StackExchange.Redis是有超时的bug，最后找到csredis解决了问题。把StackExchange.Redis替换掉了。

---

DevOps StackExchange 连线 Redis 出现 Timeout

同事反应出现大量 Redis 连线 Timeout 的错误，因为 Redis 上存放 Session 跟许多 config cache 资料，如果 Redis 异常会严重影响线上服务，所以立马需要进行除错

首先使用 Redis-cli 确认服务仍正常执行中，接著执行了 Redis Benchmark 检查 server 回应，数据并没有发现异常，使用 Redis Desktop Manager 连线 Redis 资料也可以正常取得，推测 Redis server 本身应该是正常的

接著确认同事的使用情境后发现并非全面性出现 Redis timeout 只有存取几个特定的 key 会出现问题。仔细检查后发现：引起 timeout error 的 key 都有 size 较大的特徵，推测可能是资料量太大造成的

错误讯息

• 错误讯息

2017-06-28 18:04:56,025 [17] [ERROR] [RedisObjectStore`1] 
Inner exception number - 0
Timeout performing HGETALL faqscache:******.portal.bll.appdatamanager+cachedata, inst: 1, queue: 18, qu: 0, qs: 18, qc: 0, wr: 0, wq: 0, in: 0, ar: 0, clientName: TestAPP01, serverEndpoint: 127.0.0.1:8188, keyHashSlot: 3414, IOCP: (Busy=0,Free=1000,Min=2,Max=1000), WORKER: (Busy=6,Free=8185,Min=2,Max=8191) (Please take a look at this article for some common client-side issues that can cause timeouts: http://stackexchange.github.io/StackExchange.Redis/Timeouts)
    at StackExchange.Redis.ConnectionMultiplexer.ExecuteSyncImpl[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
    at StackExchange.Redis.RedisBase.ExecuteSync[T](Message message, ResultProcessor`1 processor, ServerEndPoint server)
    at StackExchange.Redis.RedisDatabase.HashGetAll(RedisKey key, CommandFlags flags)
    at ******.Portal.BLL.Redis.RedisObjectStore`1.Get(String key)
Main exception & its inner exception Log end

解决方式

修改资料同步 timeout 设定 - 放宽 syncTimeout 时间 (预设 1000 毫秒)

1. 原始 redis 连线资讯

public static class RedisConnectionFactory
{
    
    private static readonly Lazy<ConnectionMultiplexer> Connection;
    public static IServer RedisServer;
        
    static RedisConnectionFactory()
    {
        var connectionString = "127.0.0.1:6379,127.0.0.1:6380,password=password";
        var options = ConfigurationOptions.Parse(connectionString);
        Connection = new Lazy<ConnectionMultiplexer>(() => ConnectionMultiplexer.Connect(options));
        RedisServer = GetConnection.GetServer(options.EndPoints.First());
    }
    public static ConnectionMultiplexer GetConnection => Connection.Value;
    public static IDatabase RedisDB => GetConnection.GetDatabase();
}

2. 修改后

public static class RedisConnectionFactory
{
    private static readonly Lazy<ConnectionMultiplexer> Connection;
    public static IServer RedisServer;
    static RedisConnectionFactory()
    {
        var connectionString = "127.0.0.1:6379,127.0.0.1:6380,password=password,syncTimeout =3000";
        var options = ConfigurationOptions.Parse(connectionString);
        Connection = new Lazy<ConnectionMultiplexer>(() => ConnectionMultiplexer.Connect(options));
        RedisServer = GetConnection.GetServer(options.EndPoints.First());
    }
    public static ConnectionMultiplexer GetConnection => Connection.Value;
    public static IDatabase RedisDB => GetConnection.GetDatabase();
}

心得

放宽资料同步时间后，timeout 问题确实获得解决，但还是建议同事从源头端来缩小 redis 的资料量大小，一来减少 network 传输的 io ，二来可以增加 redis 回应速度

---

StackExchange.Redis性能调优

大家经常出现同步调用Redis超时的问题，但改成异步之后发现错误非常少了，但却可能通过前后记日志之类的发现Redis命令非常慢。

PS: 以后代码都在Windows bash中运行，StackExchange.Redis版本为1.2.6

先快速重现问题和解决问题，大家先运行下面的代码

public static async Task Main(string[] args)
{
    ThreadPool.SetMinThreads(8, 8);
    using (var connection = await ConnectionMultiplexer.ConnectAsync("localhost"))
    {
        connection.PreserveAsyncOrder = false;

        var db = connection.GetDatabase(0);
        var sw = Stopwatch.StartNew();

        await Task.WhenAll(Enumerable.Range(0, 10)
            .Select(_ => Task.Run(() =>
            {
                db.StringGet("aaa");

                Thread.Sleep(1000);
            })));

        Console.WriteLine(sw.ElapsedMilliseconds);
    }
}

运行发现抛出StackExchange.Redis.RedisTimeoutException，为什么呢？是因为当前工作线程根本不够用，同步等待时已经超时。具体请看源代码

如果将上面的ThreadPool.SetMinThreads(8, 8)改成ThreadPool.SetMinThreads(100, 100)呢？是不是不抛异常了呢。

再说异步接口变慢的问题，大家先运行下面的代码：

public static async Task Main(string[] args)
{
    var tcs = new TaskCompletionSource<bool>();
    var sw = Stopwatch.StartNew();

    Console.WriteLine($"Main1: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}");

    var task = Task.Run(() =>
    {
        Thread.Sleep(10);
        Console.WriteLine($"Run1: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}");
        tcs.TrySetResult(true);
        Console.WriteLine($"Run2: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}");
        Thread.Sleep(10000);
    });

    var a = tcs.Task.ContinueWith(_ => { Console.WriteLine($"a: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}"); });
    var b = tcs.Task.ContinueWith(_ => { Console.WriteLine($"b: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}"); });
    var c = tcs.Task.ContinueWith(_ => { Console.WriteLine($"c: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}"); });

    await tcs.Task;
    Console.WriteLine($"Main2: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}");
    Thread.Sleep(100);
    await Task.Delay(10);
    Console.WriteLine($"Main3: {sw.ElapsedMilliseconds}, ThreadId: {Environment.CurrentManagedThreadId}");
}

最终输出结果发现Run1和Main2是使用相同的线程吧，而Run2的ElapsedMilliseconds基本上就是在Run1的基础上加100。

然后再回到调用Redis代码上

static async Task Main(string[] args)
{
　　 ThreadPool.SetMinThreads(100, 100);
    using (var connection = await ConnectionMultiplexer.ConnectAsync("localhost"))
    {
        var db = connection.GetDatabase(0);
        var sw = Stopwatch.StartNew();

        await Task.WhenAll(Enumerable.Range(0, 10)
            .Select(_ => Task.Run(async () =>
            {
                await db.StringGetAsync("aaa");

                Thread.Sleep(100);
            })));

        Console.WriteLine(sw.ElapsedMilliseconds);
    }
}

你们发现输出是100多还是1000多？为什么？原来是因为sdk中有一个特殊的设置，要保护异步代码执行的顺序，然后我们在GetDatabase行之前加一个代码connection.PreserveAsyncOrder = false;

然后再运行一次看看结果是多少呢？通过上面再做代码基本上可以确定异步慢是和TaskCompletionSource和关系的，具体请看sdk的源代码。

总结上面两点，简单得通过SetMinThreads和connection.PreserveAsyncOrder = false可以解决绝大部分问题，但更多其他深层次的问题怎么发现呢？

下面就要介绍StackExchange.Redis两个神器ConnectionCounters和IProfiler

1. 通过connection.GetCounters().Interactive获得的对象之后其中有三个属性非常有用

public class ConnectionCounters
{
    /// <summary>
    /// Operations that have been requested, but which have not yet been sent to the server
    /// </summary>
    public int PendingUnsentItems { get; }

    /// <summary>
    /// Operations that have been sent to the server, but which are awaiting a response
    /// </summary>
    public int SentItemsAwaitingResponse { get; }

    /// <summary>
    /// Operations for which the response has been processed, but which are awaiting asynchronous completion
    /// </summary>
    public int ResponsesAwaitingAsyncCompletion { get; }
}

1. 每个属性表示当前redis连接的待完成的命令当前所处的状态。通过字面意思就可以知道PendingUnsentItems表示已经进行待发送队列还未发送出去的命令；SentItemsAwaitingResponse表示已经发送出去但还没有收到响应结果的命令；ResponsesAwaitingAsyncCompletion则表示已经收到响应的命令，但还没有调用TaskCompletionSource<T>().TrySetResult()的命令。
   其中PendingUnsentItems和SentItemsAwaitingResponse过大的原因基本上是因为网络阻塞了，你需要检查一下网络带宽或者redis的value是否很大。
   ResponsesAwaitingAsyncCompletion则是因为await之后的代码，如上面示例中的代码，线程占用了很长的同步时间，需要优化代码和将PreserveAsyncOrder设置为false。

2. ConnectionCounters分析的是一个线程的瞬时状态，而IProfiler则可以跟踪一个请求总共执行了多少的redis命令以及他们分别使用了多长时间，具体细节请大家写代码体验。参考文档

发现问题就需要解决问题，也就需要深层次得去学习才能解决问题。我不喜欢写文章，但发现最近有好几篇说redis超时的问题，最终我还是想把自己的踩坑的心得分享给大家。

这在里说一个好消息，那就是StackExchange.Redis 2.0已经从重构了异步队列，使用管道方式解决异步慢的问题

---

StackExchange.Redis 之 操作Redis链接字符串配置（链接Redis集群）

Redis链接字符串可以提出来放到 Config文件当中：

  <connectionStrings>
    <add name="Connection_Redis" connectionString="127.0.0.1:6379,127.0.0.1:6380,127.0.0.1:6381,127.0.0.1:6382,password=123456,abortConnect=false" />
  </connectionStrings>

当有多个Redis实例时，可以设置链接多个实例，中间用逗号分隔即可（比如：使用Redis集群）。

public class RedisCacheHelper
    {
        private readonly Logger _log = LogManager.GetCurrentClassLogger();

        /// <summary>
        /// 连接字符串
        /// </summary>
        private static string _connectionString;

        /// <summary>
        /// redis 连接对象
        /// </summary>
        private static IConnectionMultiplexer _connMultiplexer;

        /// <summary>
        /// 实例化对象
        /// </summary>
        private static RedisCacheHelper _cacheHelper;
        /// <summary>
        /// 实例
        /// </summary>
        private static RedisCacheHelper _instance;

        /// <summary>
        /// 锁
        /// </summary>
        private static readonly object Locker = new object();

        /// <summary>
        /// 数据库
        /// </summary>
        private IDatabase _db;


        /// <summary>
        /// 默认链接实例
        /// </summary>
        private RedisCacheHelper()
        {
            _connectionString = ConfigurationManager.ConnectionStrings["Connection_Redis"].ConnectionString;
            _connMultiplexer = ConnectionMultiplexer.Connect(_connectionString);
            //添加注册事件
            AddRegisterEvent();
        }

        /// <summary>
        /// 获取 Redis 连接对象
        /// </summary>
        private IConnectionMultiplexer Connnection
        {
            get
            {
                if (_connMultiplexer == null || !_connMultiplexer.IsConnected)
                {
                    lock (Locker)
                    {
                        if (_connMultiplexer == null || !_connMultiplexer.IsConnected)
                        {
                            _connMultiplexer = ConnectionMultiplexer.Connect(_connectionString);
                        }
                    }
                }
                return _connMultiplexer;
            }
        }

        /// <summary>
        /// 获取指定db，默认不指定
        /// </summary>
        /// <param name="db"></param>
        /// <returns></returns>
        private IDatabase GetDatabase(int db = -1)
        {
            return Connnection.GetDatabase(db);
        }

        /// <summary>
        /// 调用实例，通过该实例调用Redis
        /// </summary>
        public static RedisCacheHelper Instance
        {
            get
            {
                if (_cacheHelper != null) return _cacheHelper;
                lock (Locker)
                {
                    if (_cacheHelper != null) return _cacheHelper;
                    _cacheHelper = new RedisCacheHelper();
                }
                return _cacheHelper;
            }
        }

        #region 注册事件

        /// <summary>
        /// 添加注册事件
        /// </summary>
        private void AddRegisterEvent()
        {
            _connMultiplexer.ConnectionRestored += ConnMultiplexer_ConnectionRestored;
            _connMultiplexer.ConnectionFailed += ConnMultiplexer_ConnectionFailed;
            _connMultiplexer.ErrorMessage += ConnMultiplexer_ErrorMessage;
            _connMultiplexer.ConfigurationChanged += ConnMultiplexer_ConfigurationChanged;
            _connMultiplexer.HashSlotMoved += ConnMultiplexer_HashSlotMoved;
            _connMultiplexer.InternalError += ConnMultiplexer_InternalError;
            _connMultiplexer.ConfigurationChangedBroadcast += ConnMultiplexer_ConfigurationChangedBroadcast;
        }

        /// <summary>
        /// 重新配置广播时（通常意味着主从同步更改）
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_ConfigurationChangedBroadcast(object sender, EndPointEventArgs e)
        {
            _log.Info($"{nameof(ConnMultiplexer_ConfigurationChangedBroadcast)}: {e.EndPoint}");
        }

        /// <summary>
        /// 发生内部错误时（主要用于调试）
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_InternalError(object sender, InternalErrorEventArgs e)
        {
            _log.Error($"{nameof(ConnMultiplexer_InternalError)}: {e.Exception}");
        }

        /// <summary>
        /// 更改集群时
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_HashSlotMoved(object sender, HashSlotMovedEventArgs e)
        {
            _log.Info(
                $"{nameof(ConnMultiplexer_HashSlotMoved)}: {nameof(e.OldEndPoint)}-{e.OldEndPoint} To {nameof(e.NewEndPoint)}-{e.NewEndPoint}");
        }

        /// <summary>
        /// 配置更改时
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_ConfigurationChanged(object sender, EndPointEventArgs e)
        {
            _log.Info($"{nameof(ConnMultiplexer_ConfigurationChanged)}: {e.EndPoint}");
        }

        /// <summary>
        /// 发生错误时
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_ErrorMessage(object sender, RedisErrorEventArgs e)
        {
            _log.Error($"{nameof(ConnMultiplexer_ErrorMessage)}: {e.Message}");
        }

        /// <summary>
        /// 物理连接失败时
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_ConnectionFailed(object sender, ConnectionFailedEventArgs e)
        {
            _log.Fatal($"{nameof(ConnMultiplexer_ConnectionFailed)}: {e.Exception}");
        }

        /// <summary>
        /// 建立物理连接时
        /// </summary>
        /// <param name="sender"></param>
        /// <param name="e"></param>
        private void ConnMultiplexer_ConnectionRestored(object sender, ConnectionFailedEventArgs e)
        {
            _log.Info($"{nameof(ConnMultiplexer_ConnectionRestored)}: {e.Exception}");
        }

        #endregion
    }

以上Redis链接就配置好了，使用方式如下：首先在把集群中的主从服务都开启，3主、3从

然后在代码中进行操作验证，向缓存中插入一条数据，然后循环读写数据，循环的时候手动任意关闭Redis服务当中的 1~2个 服务器

while (true)
            {
                //设置age
                RedisCacheHelper.Instance.Set("age", "10", new TimeSpan(0, 5, 0));

                //获取age
                var getage = RedisCacheHelper.Instance.Get("age");
                Console.WriteLine(DateTime.Now.ToString("HH:mm:ss.fff") + "：" + getage);

                Thread.Sleep(1000); // 等待1s
            }

成功将缓存存入到服务器当中，运行效果如下：

此时查看Redis集群，发现主从实例都有数据了，接下来我们把其中任意1个 Redis实例关掉 (上边运行的循环代码程序不要关闭)

发现程序正常运行：

但是上边的步骤，我经过多次测试，在任意关闭某个实例的时候，偶尔会报如下错误：集群挂了

我们把写的方法注释掉，只保留读取的代码，同样会偶尔报异常。

但是大部分情况下，关掉其中一个实例，程序都正常运行：

---

使用StackExchange.Redis客户端进行Redis访问出现的Timeout异常排查

问题产生

这两天业务系统在redis的使用过程中，当并行客户端数量达到200+之后，产生了大量timeout异常，典型的异常信息如下：

Timeout performing HVALS Parser2#Hash#VersionState, inst: 1, mgr: ExecuteSelect, err: never, queue: 2, qu: 0, qs: 2, qc: 0, wr: 0, wq:> 0, in: 0, ar: 0, clientName: GS-SERVER-2894, IOCP: (Busy=0,Free=1000,Min=8,Max=1000), WORKER: (Busy=0,Free=32767,Min=8,Max=32767), Local-CPU: 0% (Please take a look> at this article for some common client-side issues that can cause timeouts: https://github.com/StackExchange/StackExchange.Redis/tree/master/Docs/Timeouts.md)

No connection is available to service this operation: HVALS Parser2#Hash#VersionState

SocketFailure on HVALS

运行环境：

Redis服务器版本：2.8.19
.net Framework版本：4.5.2
StackExchange.Redis版本：1.1.603

问题分析

首先定位问题，排除Redis基础组件本身问题，使用redis提供的benchmark工具进行测试：

redis-benchmark -h 10.200.XX.XX -p 30301 -q -n 100000 -c 300 -d 10240

由于redis使用docker提供服务因此端口映射到30301，模拟100000次真实场景请求，300并发，每次请求数据大小10K。

经测试，对常见的hset,hget,sadd,spop等短耗时操作，TPS均保持在25K-30K之间，因此初步排除docker提供的redis服务的问题。

因此问题大致定位在了业务系统代码中，即使用的redis客户端工具（StackExchange.Redis）这部分。

通过StackExchange对Timeout异常的相关信息（可见这个问题挺常见）及stackoverflow等站点上的相关内容，产生timeout异常比较常见的原因包含（但不限于）：

1：服务器资源不足；

2：耗时过长的指令（StackExchange客户端连接的只读属性TimeoutMilliseconds=1000）；

3：StackExchange阻塞任务过多（异常信息中的qs值持续增长），对这种情况，StackExchange给出的建议是实现一个复用器池（ConnectionMultiplexer Pool）并动态选取最低负载的复用器进行连接，避免一个链接timeout导致所有链接阻塞的情况；

4：CLR中Thread Pool最小按需创建线程数过小导致的等待成本（500ms），可见StackExchange的ConnectionMultiplexer使用的是线程池；

此外，在StackExchange.Redis项目的Issue中与Time out相关的主题中，也有人提及在更新StackExchange.Redis的客户端版本后（1.1.605+）该异常不再出现的问题。

问题解决

根据以上可能产生问题的原因，对业务代码做出以下修改：

1：不再继续使用StackExchange.Redis内部封装的主/从线程池，明确主/从ConnectionMultiplexer对象；

2：修改CLR的Thread Pool最小创建线程阈值数量；

3：在ConnectionMultiplexer单例视线中加入对其IsConnected属性的判断，在其连接断开后手动释放资源并重新连接；

4：避免如HVALS等可能导致慢操作的指令；

5：升级StackExchange.Redis版本至1.1.605+（目前最新版本1.1.608）。

修改完毕后进行测试，time out异常目前已排除。

StackExchange.Redis客户端（V1.1.608）经测试有这么一个特质，即，由complexer单例对象创建的IDatabase对象，在产生Timeout异常后会导致这个complexer单例对象超时，即由其创建的新的IDatabase对象也会继续Timeout，相当蛋疼。。。

实际使用过程中，由于网络各种原因，出现Timeout异常难免，但是无法恢复确实很麻烦。测试complexer对象无法dispose,close后重建。。