记录一次因没有设置访问 redis 超时时间导致的故障

工作几年来遇到故障无数，一直都没有记录过，这次遇到一个比较典型的故障，以后搞不好还会遇到，记录一下引以为戒。

故障开始

我们的服务内有很多工作线程池，每个不同的线程池会独立负责一项业务，使用不同的线程池做隔离避免不同的业务之间相互影响。我们会监控每个工作线程池的工作状态，线程池占用情况，线程池队列长度等。

故障开始后不久，我收到报警信息说某几个工作线程池比较繁忙，处于 active 状态的线程占比很高，就是这个东西很高：

(double (/ (.getActiveCount ^ThreadPoolExecutor thread-pool) thread-pool-size))

我立即开始排查。先手工用测试工具测试了一下确认服务出现异常，有的请求无响应，有的有点慢。查看监控发现当时的监控中有三个线程池 Active 线程占比较高，其中一个最严重达到了 100%。

下面这个是 Active 线程数到达 100% 的。左边是 Active 线程占比，右边是排队的 task 数量。

排查问题

一般这种 Active 线程池占比高的问题是因为突然有大量的请求过来，或者下游某个服务异常。我随后登录线上机器做了这些事情：

1. 执行了 top 先看整个机器工作情况，发现 load、进程 cpu 使用率均不高，甚至有点低于平时正常值。
2. 找到目标服务进程号，执行 pidstat -t -p XXXX 查看这个进程以及其创建的所有线程 CPU 占比发现都很低
3. 查看日志，翻了一圈没有看到异常信息记录，没有看到下游服务超时信息
4. 最后翻了一眼统计的过去几分钟服务器收到的各种请求按请求项目归类的统计信息，发现上面三个异常线程池负责的请求在过去几分钟内请求量并没有特别特别高
5. 在本机用测试工具测试又能确认上面三个线程池负责的请求确实有问题。占用达 100% 的线程池负责的请求完全无响应，其它两个有响应但个别时候会较慢。

这一圈搞完让我有点懵，因为日志上没有任何异常信息，我们的服务在访问下游服务时候都会加上超时时间，如果线程被 block 一般会在超时后恢复并打印日志，但日志上没有看到超时信息。如果不是阻塞了，就应该是某些请求过多导致线程池忙不过来，但请求计数统计上看各种请求又不多。

因为线上环境限制，我还不能立即在线上机器上去执行 stack dump 看看线程都在干什么，耽搁了好一段时间之后才能上去执行 jstack。在 dump 了线程后看到，那两个使用率占比不到 100% 的线程池没有一个线程处在 BLOCKED 之类的可疑状态，全处在 RUNNABLE 状态，都是类似：

"XXXX-thread-pool-78" #855 daemon prio=10 os_prio=0 tid=0x00007f8d0c043000 nid=0x420 runnable [0x00007f8b19e53000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <0x00000005cda06508> (a java.io.BufferedInputStream)
        at java.io.DataInputStream.readByte(DataInputStream.java:265)
        at taoensso.carmine.protocol$get_unparsed_reply.invokeStatic(protocol.clj:139)
        at taoensso.carmine.protocol$get_unparsed_reply.invoke(protocol.clj:123)
        at taoensso.carmine.protocol$get_parsed_reply.invokeStatic(protocol.clj:214)
        at taoensso.carmine.protocol$get_parsed_reply.invoke(protocol.clj:204)
        at taoensso.carmine.protocol$execute_requests.invokeStatic(protocol.clj:321)
        at taoensso.carmine.protocol$execute_requests.invoke(protocol.clj:287)
        at taoensso.carmine.protocol$with_replies_STAR_.invokeStatic(protocol.clj:343)
        at taoensso.carmine.protocol$with_replies_STAR_.invoke(protocol.clj:329)
        XXXXXXXXXXXXX 业务 stack

上面 taoensso.carmin 是我们使用的一个 redis client。这里更有迷惑性的事情是，我们这个线程池因为做的事情比较单一，耗时的操作就是同步的去访问一个 redis，即使在正常情况下线程也要么是处在 WAITING 等待请求状态，类似于：

"XXXX-pool-69" #839 daemon prio=10 os_prio=0 tid=0x00007f8cbc03a000 nid=0x410 waiting on condition [0x00007f8b1ae63000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000005c6976018> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        ......

要么处在上面列出来的等待 redis 返回数据的状态，因为处理请求特别多的时候，redis 访问虽然快但整个请求绝大多数时间依然是在等待 IO 返回，所以正常情况下 stack dump 时候很多线程也会有上面列的那个堆栈。

在那个使用率到 100% 的线程池上我才终于找到突破口，因为看到了有处于 BLOCKED 状态的线程：

"ANOTHER-XXXX-thread-pool-74" #840 daemon prio=10 os_prio=0 tid=0x00007f8ba004d800 nid=0x411 waiting for monitor entry [0x00007f8b1ad62000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at push_server.south.online_status$fn__40217$fn__40219.invoke(online_status.clj:33)
        - waiting to lock <0x00000006052a5798> (a java.lang.Object)
        .... 业务 stack

根据 stack 里写的 waiting 的 lock 地址，搜索到了占住这个 lock 的线程，发现这样的 stack:

"ANOTHER-XXXX-thread-pool-78" #855 daemon prio=10 os_prio=0 tid=0x00007f8d0c043000 nid=0x420 runnable [0x00007f8b19e53000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <0x00000005cda06508> (a java.io.BufferedInputStream)
        at java.io.DataInputStream.readByte(DataInputStream.java:265)
        at taoensso.carmine.protocol$get_unparsed_reply.invokeStatic(protocol.clj:139)
        at taoensso.carmine.protocol$get_unparsed_reply.invoke(protocol.clj:123)
        at taoensso.carmine.protocol$get_parsed_reply.invokeStatic(protocol.clj:214)
        at taoensso.carmine.protocol$get_parsed_reply.invoke(protocol.clj:204)
        at taoensso.carmine.protocol$execute_requests.invokeStatic(protocol.clj:321)
        at taoensso.carmine.protocol$execute_requests.invoke(protocol.clj:287)
        at taoensso.carmine.protocol$with_replies_STAR_.invokeStatic(protocol.clj:343)
        at taoensso.carmine.protocol$with_replies_STAR_.invoke(protocol.clj:329)
        - locked <0x00000006052a5798> (a java.lang.Object)
        XXXXXXXXXXXXX 业务 stack

我才意识到是访问下游 redis 出现问题。上面堆栈虽然是 RUNNABLE 但几次 stack dump 之间线程堆栈完全没有变化，连 lock 的 id 都没有变过，才明白是线程卡在了等待读 redis 上。最后才发现是这个 redis 所在机器宕机，并且我们服务访问这个 redis 的地方没有加超时。。。。。

问题原因

出现问题的原因罗列一下是这样：

1. 我们代码访问 redis 时候没有设置超时时间，会一直等待 redis 的响应。我先入为主认为我们不会没设置超时导致了问题排查陷入歧途
2. 目标 redis 当时是所在机器突然宕机，类似于直接拔电源的效果，所以 TCP 连接完全没时间去处理断开
3. client 与 redis 的 PING PONG 无效，因为这里是卡在拿一个 client 连接去请求 redis，请求已经发出去在等待结果，这个状态下我们使用的 client 是不会再发 PING PONG 的。PING PONG 只用在探测 idle 连接是否还有效的时候。已经处在被占用状态的 redis client 是不会再用 PING PONG 做探测的。

教训

1. 访问 remote 服务时候一定要带着超时，即使是 long poll 也最好有超时。如果实在无法带超时，最差也得有其它机制去检查 remote 服务是否正常，在不正常时候去取消没带超时的请求，但这个检查机制不容易做到可靠
2. 从上面两个使用率不到 100% 的线程池监控能看到，线程池占比是一条直线。这个也是一个信号，说明很可能有线程是完全卡住了，不然不该这么稳定的处于被占用状态。另一个占用率到 100% 的线程池的监控看到，占用率是从某个值逐步上升的，主要是因为我们内部实现中有个锁，一开始 redis 挂掉后只有一部分线程被 Block 在等待 IO 返回数据上，但这种线程在访问 redis 之前会拿锁，所以 Block 之后无法释放锁，别的正常线程想加锁时也会被 Block 导致线程池内所有线程处于 Block 状态。并且可以从监控看到，这个占用率到 100% 的线程池在出现问题后，线程池的占用率是逐步上升到 100% 的，而不是突然升高。所以一个关键的事情是，当看到线程池占比是一条直线的时候，得想到可能是线程完全被 BLOCK，即使其状态处在 RUNNABLE
3. 线上机器很多时候都不好上去执行 jstack，可以在保证安全的前提下考虑在服务上开口子去执行 (Thread/getAllStackTraces) 将 stack 打在日志里。开口子方式类似于留一个内部 HTTP 能调用的路径，或者一个 RPC method。需要注意的是，(Thread/getAllStackTraces) 开销较大很大，跟 jstack 一样最好在出问题时候执行，再就是这个方式打印的 stack 会比 jstack 工具打印出来的信息少一些，比如会少 lock 了哪些锁，block 在了哪个锁，锁的地址是什么等。
4. 单一一次 stack 记录往往很难提供足够的有效信息，经常是需要在固定时间间隔连续的打多次 stack 来比较线程 stack 变化，也许需要个工具去自动化的做这个事情会更好。出问题时候人本来就急，很可能漏看信息。

还一个想说的

还想说一下由本次故障想到的 redis 的 pub/sub 功能问题。

redis 的 pub/sub 功能有这么一些特点：

1. 没有离线消息，一个 client 只有连上 redis 并 subscribe 之后才能收到 event 通知，如果因为某些原因异常掉线了，则掉线期间的 event 会丢失；
2. 为了持续收到 event，连接不能断开，得 subscribe 后一直这么挂着；

联系本次问题就想到一个事情，如果我们希望 client subscribe 一次后一直能收到 event，那我们可能会倾向于不去设置 timeout 时间，但如果 redis 突然宕机，可能 client 无法感知到 TCP 连接断开，就导致这个 client 一直收不到 event 事件。我还找到了一个 redis 的 issue 说这个事情：PING not allowed while subscribing · Issue #420 · antirez/redis · GitHub 。大致上说就是 redis 3.2 后，在 subscribe 后连接需要定时去 ping redis server 来判断连接是否还活着。

所以，在使用 redis 的 pub/sub 功能时一定要确认使用的 client 是否支持在 subscribe 后会自动发 ping 去探测连接状态。如果 client 不支持，就得采用 workaround 去处理这个问题，要么是设置 read socket timeout 在 subscribe channel 且一直没 event 来的时候抛异常主动退出等待，接下来再重 subscribe，这么一直循环下去。或者如果 client 有较大自由度，可以考虑重复在已经执行过 subscribe 的连接上再次执行 subscribe。总之得开动想象力折腾一番。

拿我们在使用的 taoensso.carmin redis client 来举例，它在使用 redis pub/sub 功能时需要使用特殊的 with-new-listener 而在 with-new-listener 的说明里明确写的：

[1] You probably do NOT want a :timeout for your conn-spec here.

即其建议不要去为使用 pub/sub 的连接设置 timeout。但 taoensso.carmin 没有实现 subscribe 的状态下发 ping 探测连接状态，又不支持重复 subscribe，所以 workaround 想了一下可能只有为 with-new-listener 设置 timeout，并且处理 timeout 异常，每次 timeout 了后去重新再 subscribe。如果是初次连接 redis 超时，报的也会是 SocketTimeoutException 异常附带的 msg 会是 "Connect timed out"。如果是 subscribe 成功后因为设置了 timeout 而抛 SocketTimeoutException 异常，附带的 msg 会是 "Read timed out"。