问题

在《消息服务单实例问题导致消息发送延迟》的故障中有一个很诡异的事情:

异常实例在 22点03分隔离之后仍然在处理请求,但是从调用端的视角来看隔离之后就没有报错了。

经过再三核对监控和日志,可以确认隔离操作执行成功了,在隔离之后调用端就没有再调用异常实例,异常实例在 22点03分之后处理的请求应该是之前积压的,持续时间长达 12 分钟,一时无法判断是积压在哪里。

另外通过 trace 信息可以确认,隔离之后处理的请求都是在隔离之前发送的。(请求中的 consumerStartTIme 记录了请求发送时间)

TCP 基础知识

1. 数据流中有很多的buffer,例如 tcp receive buffer 和 netty 的 channelbuffer

问题-LMLPHP

2. 即使是客户端发送 FIN 关闭连接了,服务端也可以继续读 receive buffer 中的数据

问题-LMLPHP

积压估算

问题-LMLPHP

根据监控来看 20:03 分隔离之后,处理了 261.7K 的请求。

在隔离之前有 6 分钟的处理报错,调用端使用一致性哈希路由,aft 的最大降权值为 1,不能完全摘除异常实例的流量,所以最糟糕的情况下 30 个调用端实例可以向异常实例发送 6 * 30 * 100 * 60 = 1080K 个请求。

而异常实例的 tcp receive buffer 配置是 1M,实际占用 2M,由于单个请求不大,以 200B 计算单个连接可以积压 10485 个请求,另外 netty3 还有个 64K 的 ChannelBuffer 也会积压一些数据,总共有 30 个调用端(也就是30个连接),所以积压的请求完全可以导致上面的现象。

模拟验证

正常情况下服务的处理能力不会这么差,即使有积压在 buffer 中的请求,也会很快返回错误信息(提交业务线程失败,返回 Threadpool is full)。

出现上面的积压现象主要受两个因素影响:

  1. 异常实例所在的宿主机负载非常高

  2. 异常实例自身 GC 很严重(主要也是受 1 的影响)

总而言之,就是故障期间异常实例的处理能力很低,所以可以通过主动睡眠处理线程模拟当时的情况。

在 netty3 将请求提交给 moa 业务线程池之前 sleep 2s,模拟负载高请求处理慢的情况,然后起一个 client 单连接发送请求,理论上会在 1s 超时后重新发送,发送 5分钟,也就是 300 个请求后退出。

连接关闭时服务端视角看 receive buffer 还有量,并且程序还在正常读取:

问题-LMLPHP

处理的最后一条请求的时间是 15:58:24,积压了 3 分钟。

同宿主机其它实例的情况

xxx-service-65c9d4997-h6chd

最后收到请求的时间点 2021-04-07 22:05:42,而该请求发送的时间为 2021-04-07 22:04:41,也就是请求积压了 36s。

z该实例请求积压时间没有那么长的原因是:调用端的路由策略不是一致性哈希,没有那么多重试请求过来。

06-24 15:47