StackExchange.Redis Timeout performing 超时问题
最近在做的一个项目,用的.net core 2.1,然后缓存用的Redis,缓存相关封装是同事写的,用的驱动是StackExchange.Redis version 2.0.571 ,一直听说这个驱动并发情况下有TimeOut bug,项目开发差不多后,我压测了一下,简单的模拟30个用户持续访问某一个有用到缓存的查询接口,结果这么小的压力下超时异常出现:Timeout performing GET
最近在做的一个项目,用的.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
毫秒)
- 原始
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();
}
- 修改后
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
- 通过
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; }
}
-
每个属性表示当前redis连接的待完成的命令当前所处的状态。通过字面意思就可以知道
PendingUnsentItems
表示已经进行待发送队列还未发送出去的命令;SentItemsAwaitingResponse
表示已经发送出去但还没有收到响应结果的命令;ResponsesAwaitingAsyncCompletion
则表示已经收到响应的命令,但还没有调用TaskCompletionSource<T>().TrySetResult()
的命令。
其中PendingUnsentItems
和SentItemsAwaitingResponse
过大的原因基本上是因为网络阻塞了,你需要检查一下网络带宽或者redis
的value
是否很大。
ResponsesAwaitingAsyncCompletion
则是因为await
之后的代码,如上面示例中的代码,线程占用了很长的同步时间,需要优化代码和将PreserveAsyncOrder
设置为false
。 -
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
后重建。。
更多推荐
所有评论(0)