问题背景
近期,某企业客户的应用需要迁移到其他机房的机器上。在迁移前夕的测试过程中,客户发现当同一个应用的多个Pod副本,被调度到Kubernetes多个不同节点上时,部分节点(慢节点)上的应用实例耗时显著高于其他节点,同时观察发现,这些慢节点都是迁移后的节点,请求在迁移前的节点上耗时均是正常的。

从上图中可以看到,红框中的第一个实例的耗时显著高于其他实例,而其所在的节点即为迁移后的节点上。此问题阻塞了客户的机房迁移进展,联系阿里云工程师需要帮助分析耗时出现差异的根因。
问题排查
梳理耗时点工程师在了解了需求后,首先梳理了客户系统应用的访问链路,跟进客户反馈,其问题最为严重的Gateway应用,部署形态大致如下:

基于上述信息,无法直接判断出具体的耗时点在哪?好在工程师发现,系统应用均接入到了阿里云ARMS中,想到可以通过查看调用链进一步判断耗时点。
于是,在ARMS中查看一条慢调用记录的调用链,发现刨去Gateway的下游应用耗时,有7s多的时间消耗在了Gateway应用身上,这部分的耗时包含了Gateway应用自身的执行耗时及其调用下游的网络耗时,其中和Gateway应用自身相关的耗时都在FilteringWebHandler.handle这个自定义filter上:

客户通过AOP切面实现了Gateway接口的耗时统计,并记录在了日志中,过滤同一条traceId从日志中看,业务处理逻辑耗时都是在毫秒级别,没有达到秒级。因此,此时的调查方向转向了对网络偶发延时高的怀疑上。
抓包分析
抓包通常来说是对网络耗时分析的有效利器,下一步决定在慢节点的Gateway pod中进行抓包,尝试分析耗时高的原因。

如上报文为在Gateway pod中抓取的Ingress(192.168.196.33)访问Gateway(192.168.196.102)的报文,在15:17:31(后续简称31秒)Gateway应用收到了Ingress的请求(序号115270报文),在15:17:43(后续简称43秒)Gateway应用响应回Ingress(序号171373报文)。

如上报文为在Gateway pod中抓取的Gateway(192.168.196.102)访问后端应用(192.168.196.70)的报文(根据token过滤,确保与上述请求在业务上为同一条请求),在15:17:37(后续简称37秒)Gateway向后端应用发起请求(序号140408报文),在15:17:37(后续简称37秒)Gateway收到了后端应用的响应(序号140528报文)。
根据上述两个图片中的报文,可以梳理出请求的链路以及关键的时间节点,请求的访问链路为 Ingress(192.168.196.33) -> Gateway(192.168.196.102) -> 后端应用 (192.168.196.70),Gateway应用在31秒收到了请求,37秒向后端应用发起请求,37秒后端应用返回了响应,43秒Gateway响应回Ingress。
通过如上的分析,可以得出Gateway应用和后端应用的网络之间并不存在问题,因为在Gateway向后端发起请求后,后端的返回耗时很低。时间主要消耗在Gateway 31秒收到请求,37秒才去请求后端应用,这6秒的时间里。
再拆解这6秒内的耗时,在31秒Gateway收到Post请求

在37秒Gateway连接Redis发送token(使用Post请求里面的accesstoken过滤,确保与31秒时Gateway收到的请求为同一条):

此时可以说明主要的耗时都用在向Redis发送请求,或者连接Redis上。
对比耗时正常的抓包分析,在耗时高的请求中,有很多向Redis发起连接的请求。据此推测并发请求量大的时候,连接Redis操作有堆积(可能是因为迁移后引起的跨机房访问导致耗时增加),此时需要进一步排查连接Redis耗时高的原因。
进一步过滤Redis的流,发现如下特征:
- 向后连接Redis是长链接
- 在31-37之间,复用的长链接自身没有闲着,因此推测在Redis长连接上存在“等待”的问题
6秒耗时的进一步拆解
排除了以上的网络问题,耗时高的怀疑点又回到了Gateway应用自身上,即便客户的业务日志中记录的Gateway接口耗时小于1秒(福尔摩斯曾说过:排除了一切不可能的,剩下的再不可思议,也是真相),并且耗时长问题与Redis之间的连接是有关联的。
为了进一步排查这6秒耗时的原因,在咨询了阿里云可观测相关工程师后,其介绍了目前可观测领域的Trace技术主要通过SDK或者Java Agent对一些知名框架的特定方案进行埋点,统计相关耗时,但如果出现比如用户业务逻辑等这类非埋点范围内的长耗时,可能通过Trace技术就无法观测,针对这类Trace技术无能为力的场景,其推荐我们使用ARMS的代码热点功能,该功能通过关联调用链中的 TraceId & SpanId 信息提供了调用链级别的On & Off-CPU 火焰图,可有效对 Trace 的监控盲区细节进行还原,帮助用户诊断各类常见的慢调用链问题。
由于Gateway应用底层使用Reactor框架,请求都是异步调用,需要将ARMS探针升级到最新的4.2.1才能够支持异步调用链的代码热点功能。将测试Gateway应用升级到4.2.1后开启相关功能,再次压测复现问题,同时在主机上抓取和Redis之间的连接。

通过ARMS代码热点的火焰图数据结果,引发接口调用耗时长的瓶颈终于付出水面,在一个2s多的请求中getNativeConnection()独占了1.86s,此方法是Lettuce框架用于获取应用与Redis之间的连接的方法。同时通过查看压测期间慢节点的连接情况,看到大量的连接请求有堆积的情况(recvq,sendq),并注意到 6379 Redis端口的交互只有一条连接,因此可以判断问题出来了应用Redis连接池设置出现了问题,反馈相关问题到客户后,客户查看Gateway应用中Redis连接池的配置,设置了连接的min-idle、max-idle以及max-active,但是没有配置enabled参数,查看enabled参数的默认配置,仅有在加载了org.apache.commons.pool2.ObjectPool这个类的情况下才会被置为true。因此需要添加上enabled=true的配置,并引入pool2的依赖。
protected boolean isPoolEnabled(Pool pool) {
Boolean enabled = pool.getEnabled();
return (enabled != null) ? enabled : COMMONS_POOL2_AVAILABLE;
}
private static final boolean COMMONS_POOL2_AVAILABLE = ClassUtils.isPresent("org.apache.commons.pool2.ObjectPool",
RedisConnectionConfiguration.class.getClassLoader());
至此,该现象的原因就可解释了,压测期间并发请求量大,所有请求均需要复用一条连接,导致获取Redis连接的请求排队,请求处理慢。
问题延续增加了连接池的配置后,慢节点上的应用耗时有了部分下降(平均1.3s降至680ms),但整体耗时仍然显著高于正常节点。此时可以说明增加了连接池的配置对于耗时高的问题确有缓解,但仍需继续解决耗时差异的问题。
怀疑连接池大小的配置存在合理性问题,检查连接池配置,初步查看未发现异常。

再次压测,查看与Redis之间的连接,验证连接池配置是否生效。通过netstate可以查看到发起压测请求后,和Redis之间的连接数达到了17个,Lettuce有一个额外连接用于初始化连接,此时可以发现Lettuce的连接数配置是生效的,并且连接池并没有达到瓶颈,可以排除连接数配置的问题。
再次查看耗时高接口的代码热点,发现耗时主要集中在LettuceConnectionFactory.validateConnection()方法上。同时通过在压测期间,获取问题现场的jstack,可以发现有大量的Reactor线程阻塞在了同一个monitor上。
查看LettuceConnectionFactory.validateConnection()的源码,可以发现,在验证Redis连接有效性的时候会先加锁,直到验证完成后才会释放锁。
void validateConnection() {
synchronized (this.connectionMonitor) {
boolean valid = false;
if (connection != null && connection.isOpen()) {
try {
if (connection instanceof StatefulRedisConnection) {
((StatefulRedisConnection) connection).sync().ping();
}
if (connection instanceof StatefulRedisClusterConnection) {
((StatefulRedisClusterConnection) connection).sync().ping();
}
valid = true;
} catch (Exception e) {
log.debug("Validation failed", e);
}
}
if (!valid) {
log.info("Validation of shared connection failed. Creating a new connection.");
resetConnection();
this.connection = getNativeConnection();
}
}
}
在高并发连接的场景下,由于Lettuce的线程安全特性,会导致部分线程等待获取validateConnection的锁,从而导致性能的下降。这也进一步解释了为什么连接池大小一直都处于min-idle,Gateway Reactor的线程会因锁的争抢,导致Redis连接池无法得到充分利用。
查看客户的Gateway应用的代码,可以发现在业务代码中有调用LettuceConnectionFactory.setValidateConnection(true),删掉此部分相关代码后,再次压测,rt从680ms降至380ms,与迁移前节点基本持平,至此问题解决。
总结总结出现如上问题的原因及解决方案:
- 应用在使用Lettuce Redis连接池时,未引入org.apache.commons.pool2的依赖,也未显式设置enabled参数,仅设置了max、min等参数,实际线程池配置未开启生效。需要引入org.apache.commons.pool2的依赖开启线程池。
- 应用设置了在每次获取Redis连接前,需要先验证Redis连接的有效性(validateConnection),而validateConnection方法会先对当前连接持有锁后再检测,导致部分线程阻塞在获取当前连接的锁上,降低了和Redis间的并发度,无法充分利用Redis线程池的大小。在业务代码中删除LettuceConnectionFactory.setValidateConnection(true)。
一些思考
- 同样都是没有设置Redis连接池,为什么迁移前没出现耗时高的问题,迁移后却出现了问题?
在“梳理耗时点”章节中可以看到,在慢节点上的Redis请求耗时为1.x ms,在迁移前节点上的Redis请求耗时为0.xms,请求Redis的耗时相差了5-10倍,此部分的耗时差异是由于迁移后应用访问Redis出现了跨机房调用,此部分的延迟增加是在合理范围内。在压测的并发量下,迁移前节点访问Redis的速度极快,Redis的请求可以在单条连接中得到迅速的响应,未造成Redis请求的排队。而在迁移后,节点访问Redis的耗时出现了5-10倍的增加,应用访问Redis在单条连接中出现请求堆积,放大了延迟增加的影响。
- 为什么要设置validateConnection,是否有其他的方法可以校验Redis连接的活性?
设置validateConnection为true,主要解决的是应用与Redis之间的连接长时间处于空闲状态后,空闲连接被连接池回收,但应用无法感知的问题,在客户的应用场景中,与Redis时刻处于频繁交互的状态,因此可以将validateConnection设置为false。
如果需要校验Redis连接的有效性,可以采取定时任务的方式来校验连接的活性,而非在每次getNativeConnection的时候校验
@Scheduled(cron = "0/2 * * * * *")
public void task() {
if (RedisConnectionFactory instanceof LettuceConnectionFactory) {
LettuceConnectionFactory f = (LettuceConnectionFactory) RedisConnectionFactory;
f.validateConnection();
}
}