问题产生
这两天业务系统在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 -q -n -c -d
由于redis使用docker提供服务因此端口映射到30301,模拟100000次真实场景请求,300并发,每次请求数据大小10K。
经测试,对常见的hset,hget,sadd,spop等短耗时操作,TPS均保持在25K-30K之间,因此初步排除docker提供的redis服务的问题。
因此问题大致定位在了业务系统代码中,即使用的redis客户端工具(StackExchange.Redis)这部分。
通过StackExchange对Timeout异常的相关信息(可见这个问题挺常见)及*等站点上的相关内容,产生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异常目前已排除。
2016-10-17 补充
StackExchange.Redis客户端(V1.1.608)经测试有这么一个特质,即,由complexer单例对象创建的IDatabase对象,在产生Timeout异常后会导致这个complexer单例对象超时,即由其创建的新的IDatabase对象也会继续Timeout,相当蛋疼。。。
实际使用过程中,由于网络各种原因,出现Timeout异常难免,但是无法恢复确实很麻烦。测试complexer对象无法dispose,close后重建。。