作者：昭飞，铖朴
问题背景
近期，某企业客户的应用需要迁移到其他机房的机器上。在迁移前夕的测试过程中，客户发现当同一个应用的多个 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 请求里面的 Access-Token 过滤，确保与 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 的代码热点[1]功能，该功能通过关联调用链中的 Trace 信息提供了调用链级别的 On & Off-CPU 火焰图，可有效对 Trace 的监控盲区细节进行还原，帮助用户诊断各类常见的慢调用链问题。
由于 Gateway 应用底层使用 Reactor 框架，请求都是异步调用，需要将 ARMS 探针升级到最新的 4.2.1 才能够支持异步调用链的代码热点功能。将测试 Gateway 应用升级到 4.2.1 后开启相关功能，再次压测复现问题，同时在主机上抓取和 Redis 之间的连接。
通过 ARMS 代码热点的火焰图数据结果，引发接口调用耗时长的瓶颈终于付出水面，在一个 2s 多的请求中 getNativeConnection() 独占了 1.86s，此方法是 Lettuce 框架用于获取应用与 Redis 之间的连接的方法。同时通过 netstate 命令查看压测期间慢节点的连接情况，看到大量的连接请求有堆积的情况（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），但整体耗时仍然显著高于正常节点。此时可以说明增加了连接池的配置对于耗时高的问题确有缓解，但仍需继续解决耗时差异的问题。
接下来，我们开始怀疑连接池大小相关参数设置是否合理，通过检查连接池配置，初步查看未发现明显异常。
spring.redis.lettuce.pool.max-active=64 spring.redis.lettuce.pool.enabled=true spring.redis.lettuce.pool.min-idle=16 spring.redis.lettuce.pool.max-idle=32 spring.redis.lettuce.pool.max-wait=100
再次压测，查看与 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，与迁移前节点基本持平，至此问题解决。
问题排查小结
对上述排查过程进行小结，相关问题的原因及处理办法如下：
1. 应用在使用 Lettuce Redis 连接池时，未引入 org.apache.commons.pool2 的依赖，也未显式设置 enabled 参数，仅设置了 max、min 等参数，实际线程池配置未开启生效。需要引入 org.apache.commons.pool2 的依赖开启线程池。
2. 应用设置了在每次获取 Redis 连接前，需要先验证 Redis 连接的有效性（validateConnection），而 validateConnection 方法会先对当前连接持有锁后再检测，导致部分线程阻塞在获取当前连接的锁上，降低了和 Redis 间的并发度，无法充分利用 Redis 线程池的大小。在业务代码中删除 LettuceConnectionFactory.setValidateConnection(true)。
一些思考
1. 同样都是没有设置 Redis 连接池，为什么迁移前没出现耗时高的问题，迁移后却出现了问题？
- 在“梳理耗时点”章节中可以看到，在慢节点上的 Redis 请求耗时为 1.x ms，在迁移前节点上的 Redis 请求耗时为 0.xms，请求 Redis 的耗时相差了 5-10 倍，此部分的耗时差异是由于迁移后应用访问 Redis 出现了跨机房调用，此部分的延迟增加是在合理范围内。在压测的并发量下，迁移前节点访问 Redis 的速度极快，Redis 的请求可以在单条连接中得到迅速的响应，未造成 Redis 请求的排队。而在迁移后，节点访问 Redis 的耗时出现了 5-10 倍的增加，应用访问 Redis 在单条连接中出现请求堆积，放大了延迟增加的影响。
2. 为什么要设置 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(); } }
相关链接：
[1] 代码热点
