最近有新的spring boot服务部署测试, 发现测试一段时间之后, 就无法收到返回数据, 直到调用端timeout为止.
下面是整个问题的排查过程:
1. 首先看日志, 但很遗憾日志中并没有异常信息, 没能提供有利的切入点.
2. 因为服务重启后, 能够恢复正常, 基本可以排除网络和中间件的原因, 初步判断还是服务本身有问题.
3.出问题时, 包括健康检查在内的所有请求都是无法正常返回的, 直到客户端超时为止;
但进程还在, 服务处于假死状态中了;
代码语言：javascript复制curl http://localhost:8080/actuator/health4. 查看服务的网络连接情况发现大量的CLOSE_WAIT, 这也符合超时现象;
也说明服务已经接收了请求, 但没正常结束, 导致客户端超时关闭网络资源;
再次证明服务本身有问题.
代码语言：javascript复制netstat -anop |grep 25433
tcp6 0 0 :::8080 :::* LISTEN 25433/java off (0.00/0/0)
tcp6 1 0 10.10.0.123:8080 10.10.0.41:34792 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 1 0 10.10.0.123:8080 10.10.0.41:38096 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 1 0 10.10.0.123:8080 10.10.0.41:39404 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 186 0 10.10.0.123:8080 10.10.0.41:33486 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 166 0 10.10.0.123:8080 10.10.0.137:43160 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 422 0 10.10.0.123:8080 10.10.0.128:51672 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 166 0 10.10.0.123:8080 10.10.0.137:43540 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 1 0 10.10.0.123:8080 10.10.0.41:38200 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 166 0 10.10.0.123:8080 10.10.0.137:11427 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 1 0 10.10.0.123:8080 10.10.0.41:33452 CLOSE_WAIT 25433/java off (0.00/0/0)
tcp6 0 0 10.10.0.123:22657 10.10.0.137:6380 ESTABLISHED 25433/java off (0.00/0/0)5.回过头再看下日志, 从线程名称可以发现spring boot 线程已经分配到200了, (springboot默认也是200个线程), 服务所有线程都被占满了, 再次证明服务接收了大量请求, 没有正常返回.
同时日志上并不能看出来是卡在什么位置了.
代码语言：javascript复制[http-nio-9702-exec-200] INFO => c.r.a.v.m.i.c.XxxxController - xxx start:2000080416.既然已经确定了有大量线程卡住, 就利用jstack命令帮助我们查看线程信息吧.
代码语言：javascript复制jstack -l 25433 > jstack.log大量线程都是卡在获取Redis连接的地方.
太奇怪了!!~~
Redis是使用的连接池的配置, 不应该有连接资源获取不到的情况, 不合理!!
代码语言：javascript复制"http-nio-9702-exec-200" #288 daemon prio=5 os_prio=0 tid=0x00007ffa7c111000 nid=0x2252 waiting on condition [0x00007ff9fba0d000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x0000000099822900>(a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at org.apache.commons.pool2.impl.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:590)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:441)
at org.apache.commons.pool2.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:362)
at io.lettuce.core.support.ConnectionPoolSupport$1.borrowObject(ConnectionPoolSupport.java:124)
at io.lettuce.core.support.ConnectionPoolSupport$1.borrowObject(ConnectionPoolSupport.java:120)
at org.springframework.data.Redis.connection.lettuce.LettucePoolingConnectionProvider.getConnection(LettucePoolingConnectionProvider.java:80)
7.顺便看下GC信息, 没有FullGC, 不是GC时STW导致的, 年轻代空间有些紧张, 但不会影响服务到假死的程度.
代码语言：javascript复制 jstat -gcutil 25433
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
0.00 99.82 94.52 8.26 95.45 93.88 29 1.278 0 0.000 1.2788.分析代码, 把所有与Redis有关的地方都过一遍.
(1) 首先, Redis池的配置, 通用配置, 出问题的可能性较小;
代码语言：javascript复制spring.Redis.cluster.nodes[0]=127.0.0.1:9000
spring.Redis.cluster.nodes[1]=127.0.0.1:9001
spring.Redis.cluster.nodes[2]=127.0.0.1:9002
spring.Redis.cluster.nodes[3]=127.0.0.1:9003
spring.Redis.cluster.nodes[4]=127.0.0.1:9004
spring.Redis.cluster.nodes[5]=127.0.0.1:9005
spring.Redis.lettuce.pool.max-active=10
spring.Redis.lettuce.pool.max-wait=-1
spring.Redis.lettuce.pool.max-idle=10
spring.Redis.lettuce.pool.min-idle=2
spring.Redis.timeout=2000(2) 继续, 服务中到了@Cacheable注解, 为配合解决注解中Key过期时间的问题, 自定义了一个RedisCacheConfiguration的Bean, 不常写的逻辑, 有可能出问题;
代码语言：javascript复制@Bean
public RedisCacheConfiguration cacheConfiguration(Config apolloConfig) {
RedisCacheConfiguration cacheConfig = RedisCacheConfiguration.defaultCacheConfig()
.entryTtl(Duration.ofMinutes(apolloConfig.getCacheTimeoutMinutes()));
cacheConfig.usePrefix();
return cacheConfig;
}(3) 再继续, 代码中对于数据的处理都是使用RedisTemplate, 相关配置是封装在脚手架中的, 应该不出问题;
(4) 最后, 发现了一个不一样的写法, 是将连接拿出来之后, 调用底层命令实现的功能;
代码如下:
代码语言：javascript复制Boolean set = RedisTemplate.getRequiredConnectionFactory().getConnection()
.set("Keys".getBytes(), "Value".getBytes(), Expiration.seconds(100),
SetOption.ifAbsent());但是, 没有释放连接的逻辑, 问题一定是它了,
Redis连接池中的连接耗尽, 所有线程等待连接资源释放, 导致假死.
梳理流程, 添加释放逻辑, 问题解决.
代码语言：javascript复制RedisConnection connection = null;
try {
connection = RedisTemplate.getRequiredConnectionFactory().getConnection();
Boolean set = connection
.set("Keys".getBytes(), "Value".getBytes(), Expiration.seconds(100),
SetOption.ifAbsent());
} finally {
if (connection != null) {
connection.close();
}
}上面代码本身是想利用Set命令的NX参数, 实现一个有过期时间的排他锁;
也就是指定Key不存在时, 才会添加数据, 并且设置Key的过期时间, 同时还要是原子性的;
代码语言：javascript复制set key value [EX seconds] [PX milliseconds] [NX|XX]RedisTemplate并没有封装这种多参数的set命令, 只能通过下面两个方法配合使用,
缺陷就是非原子的, 在执行expire()之前如果宕机了, 数据不能正确删除, 造成数据混乱.
代码语言：javascript复制redisTemplate.opsForValue().setIfAbsent();
redisTemplate.expire();为什么会写出这样有漏洞的代码呢, 主要有以下原因:
1.开发时, 都是以方法级单测为主, 很难发现这种资源耗尽的问题;
2.本地的集成测试时, Redis也只使用单点模式, 池资源相关问题很难被发现;
3.这段代码在多次重复调用后才会出现资源耗尽问题, 也很难发现问题;
4.涉及到的方法并不是主要逻辑范围, 代码review也容易忽略掉;
确实难发现啊..
总结下:
1.在遇到使用连接资源的时候一定要和释放资源成对出现, 养成良好的编程习惯;
2.遇到问题, 不要慌, 尽量多的收集信息, 抽丝剥茧, 分析出有用的信息;
3.平时多做积累, 遇到问题可以从多个方面着手, 也能抓住细节, 快速排查定位问题;
