背景

之前有个服务偶尔会卡死，就是进程还在，但是不能处理任何请求。
不仅是不能处理外部请求，内部一个定时给注册中心发送心跳的线程也罢工了，导致注册中心把服务节点给摘除了。
由于服务节点较多，少了一两个并不影响业务，所以也没有太关注，有时候巡检发现服务挂了，重启一下就正常了
后来我把日志接入到 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) : [ParNew
Desired 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 真是帮了大忙