线上服务器内存使用量已达到90%报警（内存泄漏）

2016-05-06中午11:56，收到“[sentry2]2016-05-06 11:56:09 xxxxxxhost xxx.xxx.xxx.xxx 内存使用已达到90.18%”报警。首先在脑海浮现的， 应该哪里出现内存泄漏了。

一、确认问题

马上到 Sentry 监控系统查看了该服务的“ 服务器监控”指标，发现其中2台机器的 内存使用量都超过了90%，另外2台尽然没有监控数据（以前是有的）。

对于另外2台服务器没有监控数据，只好先登上去查看确认一下喽。通过“ free -m”确认，线上服务器总内存共 7872MB，使用了 7098MB，还有 773MB（= 406 + 151 + 216） 空闲着，使用率为 90.16%（= 7098 / 7872）。（参考： free(1) - Linux manual page、 Linux Used内存到底哪里去了？ | 褚霸-余锋）

从问题表现来看，该业务的4台机器都出现“ 内存使用量都超过了90%”。

二、排查问题

1. 对比一下该业务“ 服务器内存占用百分比”的历史状况

1.1 3月26日业务刚上线时，服务器内存占用百分比是 45%。

1.2 4月14日之前，服务器内存占用百分比稳定在 48%。

 

 1.3 4月15日，服务器内存占用百分比突然从 48% 升到 61%。

 

1.4 4月17日，服务器内存占用百分比稳定在 67%。

 

1.5 4月18日到5月2日期间，服务器内存占用百分比稳定在 68%。

 

1.6 5月3日直到5月6日的报警期间，服务器内存占用百分比又从 68% 升到 90%。

 

从“ 服务器内存占用百分比”历史数据的异常时间点（4月17日、5月3日）来看，我们自己都没有发布上线过代码，说明不是我们引起的。

2. 查看 Sentry 监控系统的“ 进程监控”指标，运维同学发现 logagent 进程内存占用了 580MB。他们刚优化了 logagent 组件，1分钟在线平滑升级后（线上业务服务不需要重启），内存从 580MB 降到 54MB，还是很可观的。这样 服务器的空闲内存又多出了500+MB，为排查线上问题流出了更多的时间。（当时 做得不够好的地方，应该 只保留一台作为现场排查问题，重启其他机器，避免线上可能因为所有机器 OOM 而导致整个服务不可用）（当时我们都没看到 sentry_agent 进程占用了近 1.3GB ）

 

 

 3. 内存泄漏的可能性最大，先验证之

向有经验的同学请教，说内存使用量飙高，一般都是 内存泄漏引起的。因为我们线上服务使用 Java 语言开发，所以先从 JVM 垃圾收集器 GC 入手，可以比较直观地看出 JVM 内存状况。（ jstat -gcutil `pgrep -u mapp java` 1s）

 

上图输出的每个字段的含义见 jstat -gcutil 命令参考文档。从上图看， Eden 区（ Eden Space (heap)）内存占用每秒增长 1.5%， Survivor 区（ Survivor Space (heap)，S0、S1）内存占用在一次垃圾收集后增长 1.2%， Old 区（ Tenured Generation (heap)）内存占用在一次垃圾收集后增长 0.57%， Perm 区（ Permanent Generation (non-heap)）内存一直占用 59.97%。 Young GC 平均耗时为 96.7ms （ = 358.407 / 3705），Full GC 平均耗时为 74.4ms（= 7.587 / 102）。

从“ gc 监控”看，也没收到 Full GC 报警。同时查看 gc.log， ParNew GC 大约每隔几分钟触发一次， CMS GC 大约每隔5个小时触发一次，没有 Full GC。从 JVM 内存监控数据来看，说明 GC 都正常的。

3. 哪些进程用了那么多内存

从上面@褚霸在《 Linux Used内存到底哪里去了？》总结的： 内存的去向主要有3个：1. 进程消耗，2. slab消耗，3. pagetable消耗。

先看一下线上服务器的 JVM 配置（ jps -lv）：

 

2628 org. apache.catalina.startup.Bootstrap -Djava.util.logging.config.file=/home/mapp/spyder/.default/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Xms4g -Xmx4g -XX: PermSize=96m -XX: MaxPermSize=256m -Xmn2g -XX: SurvivorRatio=10 -XX:+ UseConcMarkSweepGC -XX:+ UseCMSCompactAtFullCollection -XX: CMSMaxAbortablePrecleanTime=5000 -XX:+CMSClassUnloadingEnabled -XX: CMSInitiatingOccupancyFraction=80 -XX:+ DisableExplicitGC -verbose:gc -Xloggc:/home/mapp/logs/gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+UseCompressedOops -Djava.awt.headless=true -XX:+ HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/mapp/logs/java.hprof -XX: MaxDirectMemorySize=1g -XX:+ UseCMSInitiatingOccupancyOnly -XX:+ ExplicitGCInvokesConcurrent -Dsun.rmi.dgc.server.gcInterval=2592000000 -Dsun.rmi.dgc.client.gcInterval=2592000000 -Dsun. net.client.defaultConnectTimeout=10000 -Dsun. net.client.defaultReadTimeout=30000 -Dproject.name=xxxxxx -Djava.endorsed.dirs=/usr/local/tomcat/endorsed -D catalina.base=/home/mapp/spyder/.default -D catalina.home=/

从 JVM 配置来看，最大内存为 4GB。

接着就是通过“ top -M”（按 RES字段排序：按 f，然后再按 q）观察哪些进程占用的内存不正常。

 

top 命令的 VIRT 字段表示虚拟内存，而 RES 字段才表示实际的使用内存。从上图（数据是事后伪造的，因为没保存当时现场，但量级和当时事故现场差不多）可以很清晰地看到，java 进程占用了 4.1g 内存，和 JVM 配置一样；两个 sentry-agent 进程尽然分别占用了 1.6GB 和 1.2GB（好吓人）。

 sentry-agent 是一个收集日志的客户端，为什么会占用这么多的内存呢？向负责该服务的开发同学反馈，证实确实有问题，他们好像也发现问题了，他们答应当天下午修复问题。凭直觉，问题应该就出现在这里了。先让运维同学 重启了 sentry-agent 进程，内存占用百分比一下子就降到了 59%，说明 此问题的大部分原因是这里引起的。此数据 与4月15日吻合，但与最开始的48%数据还有差距，这个还需要进一步排查。因为从 GC 来看，自身应用程序没发现内存泄漏问题，需要深入探究一下。

 上述4台机器，前面2台使用 Docker 虚拟化，后面2台使用 KVM 虚拟化。内存占用百分比相差10+个点（相差 900+MB），注意是由于 slabs 消耗不一样引起的（参考@褚霸的文章）。

KVM 虚拟化：

$ echo `cat /proc/slabinfo |awk 'BEGIN{sum=0;}{sum=sum+$3*$4;}END{print sum/1024/1024}'` MB
139.037 MB

Docker 虚拟化：

$ echo `cat /proc/slabinfo |awk 'BEGIN{sum=0;}{sum=sum+$3*$4;}END{print sum/1024/1024}'` MB
1177.34 MB

问题解决前后，“内存占用百分比”对比图：

 看了其他监控指标，发现“ 服务器线程总数”从680下降到400，说明 sentry-agent 存在线程泄漏问题。

 

至此，本问题算是解决了大部分，线上服务器内存暴涨问题得到了解决。（在群里反馈，其他服务先前就已经出现了此问题，但一直没有去排查，我也是醉啦，就不担心出现 OOM 吗？就不担心整个服务都不可用吗？这个问题解决得到 Leader 的赞还是很开心滴）

写博客确实花很多时间和精力，但回顾问题整个处理过程并反思处理思路，还是有很多地方可以改进（不懂时就上网查资料，了解清楚），收获颇多。（感谢每一个问题！）

祝大家玩得开心！