场景:
某个读取应用信息列表的接口突然出现大量异常和超时,该接口主要读取出Redis缓存中的全部应用列表,再进行业务过滤返回结果数据,然后看异常信息如下所示。
部分关键异常日志如下:
IOCP: (Busy=0,Free=1000,Min=100,Max=1000),
WORKER: (Busy=82,Free=32685,Min=100,Max=32767),
Local-CPU: unavailable
看日志信息的意思是CPU资源不可用,导致了Redis请求的阻塞,这里记录一下出现原因和解决方式:
1. 在超时异常中,是否有很多 busyio 或 busyworker 线程?
CLR ThreadPool有两种类型的线程 - “工作线程”和“I/O 完成端口”(也称为 IOCP)线程。
- 工作线程用于处理 Task.Run(...) 或 ThreadPool.QueueUserWorkItem(...) 方法时。当工作需要在后台线程上发生时,这些线程也被CLR中的各种组件使用。
- 当异步IO发生时(例如从网络读取),使用IOCP线程。
线程池根据需要提供新的工作线程或I / O完成线程(无任何调节),直到达到每种类型线程的“最小”设置。 - 默认情况下,最小线程数设置为系统上的处理器数。
一旦现有(繁忙)线程的数量达到“最小”线程数,ThreadPool将调节每500毫秒向一个线程注入新线程的速率。 如果你的系统需要一个IOCP线程的工作,线程池马上可以分配出线程工作。 但是如果工作突发超过配置的“最小”设置,那么在处理一些工作时会有一些延迟,因为ThreadPool会等待两个事情之一发生:
- 现有线程可以*处理工作
- 连续 500ms 没有现有线程空闲,因此创建一个新线程。
基本上,这意味着当忙线程数大于最小线程时,在应用程序处理网络流量之前,可能需要付出500毫秒的延迟。 此外,重要的是要注意,当现有线程保持空闲超过15秒(记忆中是的),它将被清理,这个增长和收缩的循环可以重复。
StackExchange.Redis打印错误消息如下:
System.TimeoutException: Timeout performing GET MyKey, inst: 2, mgr: Inactive, queue: 6, qu: 0, qs: 6, qc: 0, wr: 0, wq: 0, in: 0, ar: 0,
IOCP: (Busy=6,Free=994,Min=4,Max=1000),
WORKER: (Busy=3,Free=997,Min=4,Max=1000)
在上面的错误消息中,IOCP信息行中,忙碌线程数量为6,设置的最少线程数量为4,这时候忙碌IO线程数量大于最少线程数量,这意味着会有两个请求的耗时会大于500ms。
IOCP 或 WORKER 线程的增长受到限制,StackExchange.Redis 可能会超时。所以当请求数量突然上涨时,服务中并没有足够的线程资源可以使用,线程池会有很大的线程初始化压力,一定的堆积之后,StackExchange.Redis便会超时。
所以为了更好的性能考虑,不建议将线程池的工作线程和IO线程最小数量设置为默认值,具体的值可以根据服务的请求压力合理设置,一般200左右是比较合理的值,具体关于线程池设置的详细信息在我另一篇博客中有写到:
关于使用ThreadPool.SetMinThreads方法提升API服务响应性能的总结
2. 有没有命令需要在 redis 服务器上处理很长时间?
可能有一些命令需要很长时间才能在redis服务器上处理,导致请求超时。 长时间运行的命令的很少例子有 mget有大量的键,键*或写得不好的lua脚本。 可以运行通过 SlowLog 命令查看是否有请求花费比预期更长的时间。
3. 在向Redis发出的几个小请求之前是否有大的请求超时?
错误消息中的参数“qs”告诉您有多少从客户端发送到服务器,但尚未处理响应的请求。 对于某些类型的加载,您可能会看到此值不断增长,因为 StackExchange.Redis 使用单个TCP连接,并且一次只能读取一个响应。 即使第一个操作超时,它也不会停止 向服务器发送/从服务器发送 数据,其他请求也会被阻塞,直到该操作完成。 从而,导致超时。 一个解决方案是通过确保redis-server缓存对于您的工作负载足够大并将大值分割为更小的块来最小化超时的可能性。
另一个解决方案是在客户端中使用 ConnectionMultiplexer 对象池,并在发送新请求时选择“最小化加载”ConnectionMultiplexer。 这样可能会防止单个超时导致其他请求也超时。