问题背景
近期，某企业客户的应用需要迁移到其他机房的机器上。在迁移前夕的测试过程中，客户发现当同一个应用的多个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();
}
}