日常 Bug 排查-系统失去响应-Redis 使用不当

前言

日常 Bug 排查系列都是一些简单 Bug 排查，笔者将在这里介绍一些排查 Bug 的简单技巧，同时顺便积累素材^_^。

Bug 现场

开发反应线上系统出现失去响应的现象，收到业务告警已经频繁 MarkAndSweep(Full GC)告警。于是找到笔者进行排查。

看基础监控

首先呢，当然是看我们的监控了，找到对应失去响应的系统的 ip，看下我们的基础监控。

机器内存持续上升。因为我们是 java 系统，堆的大小一开始已经设置了最大值。

--XX:Xms2g -Xmx2g

所以看上去像堆外内存泄露。而 FullGC 告警只是堆外内存后一些关联堆内对象触发。

看应用监控

第二步，当然就是观察我们的应用监控，这边笔者用的是 CAT。观察 Cat 中对应应用的情况，很容易发现，其 ActiveThread 呈现不正常的现象，竟然达到了 5000+多个，同时和内存上升曲线保持一致。

jstack

java 应用中遇到线程数过多的现象，首先我们考虑的是 jstack，jstack 出来对应的文件后。我们 less 一下，发现很多线程卡在下面的代码栈上。

"Thread-1234    java.lang.Thread.State: WAITING (parking)        at sun.misc.Unsafe.park        ......        at org.apache.commons.pool2.impl.LinkedBlockingQueue.takeFirst        ......        at redis.clients.util.Pool.getResource

很明显的，这个代码栈值得是没有获取连接，从而卡住。至于为什么卡这么长时间而不释放，肯定是由于没设置超时时间。那么是否大部分线程都卡在这里呢，这里我们做一下统计。

cat jstack.txt | grep 'prio=' | wc -l ======> 5648cat jstack.txt | grep 'redis.clients.util.Pool.getResource' ======> 5242

可以看到，一共 5648 个线程，有 5242，也就是 92%的线程卡在 Redis getResource 中。

看下 redis 情况

netstat -anp | grep 6379 tcp 0 0 1.2.3.4:111 3.4.5.6:6379 ESTABLISHED......

一共 5 个，而且连接状态为 ESTABLISHED，正常。由此可见他们配置的最大连接数是 5(因为别的线程正在得到获取 Redis 资源)。

Redis 连接泄露

那么很自然的想到，Redis 连接泄露了，即应用获得 Redis 连接后没有还回去。这种泄露有下面几种可能:情况 1:

情况 2:

情况 3：调用 Redis 卡住，由于其它机器是好的，故排除这种情况。

如何区分

我们做个简单的推理:如果是情况 1，那么这个 RedisConn 肯定可以通过内存可达性分析和 Thread 关联上，而且这个关联关系肯定会关联到某个业务操作实体(例如 code stack or 业务 bean)。那么我们只要观察其在堆内的关联路线是否和业务相关即可,如果没有任何关联，那么基本断定是情况 2 了。

可达性分析

我们可以通过 jmap dump 出应用内存，然后通过 MAT(Memory Analysis Tool)来进行可达性分析。

首先找到 RedisConn

将 dump 文件在 MAT 中打开，然后运行 OQL:

select * from redis.clients.jedis.Jedis (RedisConn的实体类)

搜索到一堆 Jedis 类，然后我们执行

Path To GCRoots->with all references

可以看到如下结果:

redis.clients.jedis.Jedis    |->object         |->item            |->first                |->...                    |->java.util.TimerThread                |->internalPool

由此可见，我们的连接仅仅被 TimerThread 和 internalPool(Jedis 本身的连接池)持有。所以我们可以判断出大概率是情况 2，即忘了归还连接。翻看业务代码:

伪代码void lock(){    conn = jedis.getResource()    conn.setNx()    // 结束,此处应该有finally{returnResource()}或者采用RedisTemplate}

最后就是很简单的，业务开发在执行 setNx 操作后，忘了将连接还回去。导致连接泄露。

如果是情况 1 如何定位卡住的代码

到此为止，这个问题时解决了。但是如果是情况 1 的话，我们又该如何分析下去呢？很简单，我们如果找到了 jedis 被哪个业务线程拥有，直接从 heap dump 找到其线程号，然后取 Jstack 中搜索即可知道其卡住的代码栈。

jmap:redis.clients.jedis.Jedis    |->Thread-123
jstack:
Thread-123 prio=...    at xxx.xxx.xxx.blocked

总结

这是一个很简单的问题，知道套路之后排查起来完全不费事。虽然最后排查出来是个很低级的代码，但是这种分析方法值得借鉴。