背景

之前有个服务偶尔会卡死，就是进程还在，但是不能处理任何请求。

不仅是不能处理外部请求，内部一个定时给注册中心发送心跳的线程也罢工了，导致注册中心把服务节点给摘除了。

由于服务节点较多，少了一两个并不影响业务，所以也没有太关注，有时候巡检发现服务挂了，重启一下就正常了

后来我把日志接入到 ELK 上，并且一段时间内没有日志输出会发出告警，这个问题才算是能比较及时的发现了

初步分析

一开始，我试图发现问题出现的某种规律，经过研究，我发现问题的出现是没有什么规律的

一般多发于业务高峰期，但也有在业务量最低峰的时候卡死过有时候重启了能连续正常运行一周多，有时候上午刚重启过，下午又卡死了

这就让人头大了，我只好在代码里加了些日志和调试，想找出问题来，这还真让我发现了一点规律

在服务正常运行时，内存占用基本是平滑的，在 50% 上下浮动，但从某个时间点开始，内存占用就开始直线上升，从 50% 很快上涨到 90% 多此时，服务里各接口的响应时间会变慢，我监控了一个调用较为频繁的接口，正常情况10 ms 就返回了， 但出问题时，其响应时间逐渐从 10 ms 到 数百毫秒，几秒，几十秒，直至服务卡死不再响应

最初我以为我缓存的数据量太大了，比如有个业务要基于 ip 地址返回用户所在的国家，我们利用开源的 GeoLite2 实现的，每个查询过的 ip 都会缓存起来

于是我调整了缓存的容量和过期策略，经过观察后发现没什么效果，正常情况下内存占用就是 50% 左右，一旦出问题了，很快就飙涨到 90% 以上，应该和缓存无关

后来我把目光转移到 redis 上，会不会是 redis 抽风了呢？

我研究了 redis 的慢日志，还真有发现，有个同事使用了 keys * 这样的命令，响应时间高达 400 多 ms，把这类的命令全部改成 scan 后，响应时间超过 100 ms 的慢日志已经没有了，但是服务神秘卡死的问题还是没有解决

GC

我调出 GC 日志，发现在出问题的时候，会频繁的 full GC，但是并不能释放内存

先看下正常情况的 GC

{Heap before GC invocations=0 (full 0): par new generation   total 2764800K, used 2457600K [0x00000005be000000, 0x0000000679800000, 0x0000000679800000)  eden space 2457600K, 100% used [0x00000005be000000, 0x0000000654000000, 0x0000000654000000)  from space 307200K,   0% used [0x0000000654000000, 0x0000000654000000, 0x0000000666c00000)  to   space 307200K,   0% used [0x0000000666c00000, 0x0000000666c00000, 0x0000000679800000) concurrent mark-sweep generation total 5120000K, used 0K [0x0000000679800000, 0x00000007b2000000, 0x00000007f0800000) Metaspace       used 61238K, capacity 62908K, committed 63104K, reserved 1105920K  class space    used 7095K, capacity 7455K, committed 7552K, reserved 1048576K[GC (Allocation Failure) : [ParNewDesired survivor size 157286400 bytes, new threshold 6 (max 6)- age   1:   80286472 bytes,   80286472 total: 2457600K->79036K(2764800K), 0.0835217 secs] 2457600K->79036K(7884800K), 0.0836609 secs] [Times: user=0.34 sys=0.06, real=0.09 secs] Heap after GC invocations=1 (full 0): par new generation   total 2764800K, used 79036K [0x00000005be000000, 0x0000000679800000, 0x0000000679800000)  eden space 2457600K,   0% used [0x00000005be000000, 0x00000005be000000, 0x0000000654000000)  from space 307200K,  25% used [0x0000000666c00000, 0x000000066b92f1e8, 0x0000000679800000)  to   space 307200K,   0% used [0x0000000654000000, 0x0000000654000000, 0x0000000666c00000) concurrent mark-sweep generation total 5120000K, used 0K [0x0000000679800000, 0x00000007b2000000, 0x00000007f0800000) Metaspace       used 61238K, capacity 62908K, committed 63104K, reserved 1105920K  class space    used 7095K, capacity 7455K, committed 7552K, reserved 1048576K}

可以看到，这是一次 minor gc，在 GC 前，eden 区占用是 100%，而 from、to 区占用是 0%，GC 后 eden 区占用是 0%， from 占用 25%，to 占用 0%

这说明 GC 回收了大量内存，而出问题时候的日志是这样的

[Full GC (Allocation Failure) [CMS: 6143999K->6143999K(6144000K), 12.6006547 secs] 8908539K->8908446K(8908800K), [Metaspace: 88611K->88611K(1132544K)], 12.6008250 secs] [Times: user=12.55 sys=0.06, real=12.60 secs] Heap after GC invocations=1345 (full 765): par new generation   total 2764800K, used 2764446K [0x00000005be000000, 0x0000000679800000, 0x0000000679800000)  eden space 2457600K, 100% used [0x00000005be000000, 0x0000000654000000, 0x0000000654000000)  from space 307200K,  99% used [0x0000000666c00000, 0x00000006797a78a0, 0x0000000679800000)  to   space 307200K,   0% used [0x0000000654000000, 0x0000000654000000, 0x0000000666c00000) concurrent mark-sweep generation total 6144000K, used 6143999K [0x0000000679800000, 0x00000007f0800000, 0x00000007f0800000) Metaspace       used 88611K, capacity 91828K, committed 92928K, reserved 1132544K  class space    used 9185K, capacity 9792K, committed 9984K, reserved 1048576K}{Heap before GC invocations=1345 (full 765): par new generation   total 2764800K, used 2764446K [0x00000005be000000, 0x0000000679800000, 0x0000000679800000)  eden space 2457600K, 100% used [0x00000005be000000, 0x0000000654000000, 0x0000000654000000)  from space 307200K,  99% used [0x0000000666c00000, 0x00000006797a78a0, 0x0000000679800000)  to   space 307200K,   0% used [0x0000000654000000, 0x0000000654000000, 0x0000000666c00000) concurrent mark-sweep generation total 6144000K, used 6143999K [0x0000000679800000, 0x00000007f0800000, 0x00000007f0800000) Metaspace       used 88611K, capacity 91828K, committed 92928K, reserved 1132544K  class space    used 9185K, capacity 9792K, committed 9984K, reserved 1048576K

此时已经是 full gc 了，GC 前 eden 占用 100%， from 占用 99%， GC 后的占用依然是 eden 100%， from 99%，完全没有释放出内存

这也导致了 full GC 不断的重试，进入了一个 GC 的死循环

从日志也可以看到，此时 full GC 基本是不停歇的

OK，问题找到了，因为 full GC 过于频繁，而又无法释放出内存，程序一边要挂起等待 GC 结束，一边又无法创建新的对象，就无法响应外部请求，也无法维持与注册中心的心跳，最终就卡死了

问题是，为什么会频繁的 full GC 呢？多个服务节点，硬件环境也基本一致，为什么有的运行的好好的，有的就内存飙涨了呢？

我还一度想过是不是 jvm 参数配置有问题，或者是不是要换个垃圾收集器，甚至是升级 jdk 的版本诸如此类的

jmap & EMA

在又一次卡死后，我用 jmap 把内存堆栈给 dump 出来了，命令如下

jmap -dump:format=b,file=opt/dump.log 29119

这个文件有 10 多G，我先是用 jdk 自带的 jvisualvm 来打开，这个工具功能有限，可以看到内存里有大量 char[]，String，还有业务里的一些对象，比如 User 之类的，这个是比较奇怪的，我们的总用户数也不过百万，但是内存里竟然有几百万的 User 实例，而我之前怀疑过的缓存对象，压根排不上号，不过也就这些了，没有更进一步的信息

我又用 elipse 的插件 memory analyzer 来分析，结果还是 EMA 插件技高一筹，直接给我定位到代码了

首先是打开 memory analyzer 视图

接下来就打开 dump 文件即可，EMA 会列出可能导致内存泄漏的疑点，甚至精准到某个方法

那就看下代码吧，这一看果然有 bug

我们这个业务是如果用户发布了一个动态，就查询出他的粉丝，并将该动态同步给其粉丝，这里的代码是调用另一个微服务，获取其所有粉丝

考虑到有的用户粉丝量较多，所以这个接口是分页的，每页返回 100 个用户。问题就出在这里

如果某一页返回的用户数少于 100，那就认为已经获取到了所有用户，退出否则就循环调用该接口，直到返回的用户数少于 100

问题是，在循环时，没有把页码数递增，这样如果某个用户的粉丝数多于 100，就限于死循环了

这个功能不是个很常用的功能，而粉丝数多于 100 的用户也很少，这样也很好的解释了为什么有时候能正常运行一周以上

修改了这个 bug 后，发布上线，问题完美解决

总结

基于经验我一直不认为代码有问题，因为问题只是偶发，且没有什么规律，我当时怀疑过同一个服务器上运行的其他程序占用了 IO 或者 CPU 等资源，或者是 redis 响应慢，甚至是 jvm 的垃圾回收配置有问题…结果最终还是代码里的一个低级错误导致的

另外就是 EMA 真是帮了大忙