今天一台测试服务器频繁出现老年代gc的报警,正常情况下测试服务器流量应该很小不应该出现这种情况。因为是测试服务器所以可以忽略这个报警,但是出于好奇还是想一探究竟。 这里有必要先介绍下服务器的jvm配置,

1g内存 新生代老年代比例为1:4 我就是说老年代800MB左右

登上服务器,查看日志,发现奇怪的情况日志在某一时刻停止了,而且出现了一条日志被截断的情况。一般出现这种情况,原因多半是进程终止或者磁盘空间不足,使用下面的命令查看磁盘空间,

df -h

可以看到磁盘果然占用了100%。尝试删除了一个前一天的日志,腾出了一些空间,新的日志出现了,同时gc的报警也消失了。这二者之间又什么联系呢?为了搞明白这一点,使用下面的命令查找进程pid

jps

然后使用

jmap -dump:format=b,file=t.bin pid

导出进程的堆文件。然后使用heap analyzer打开堆文件,找到内存泄露分析,可以看到如下的数据, /assets/images/gc1.png

可以看到logback相关的数据占用了堆栈的绝大部分,达到了400+MB。正常情况下除非系统有大量的日志产生,否则不会出现堆中有这么多日志的数据。结合之前磁盘满了的现象我们可以做出下面的推断:

1.日志将磁盘打满
2.进程产生新的日志,日志进入到logback后,进程继续运行,因为logback是异步的。
3.因为磁盘满了,logback的数据堆在内存中,无法写入到磁盘
4.内存中的日志起初在新生代,由于一直无法释放进入到老年代,由于老年代只有800MB,所以很容易达到CMS配置的触发老年代gc的阈值,最终导致老年代gc

由于正常的情况下测试服务器日志很少,要经过很长一段时间才会出现上面的情况。如果想短时期内将磁盘打满一定是有大量的日志产生,再次登录到服务器,查看日志可以看到系统在打印大量的异常,日志文件增长的速度很快,至于为什么会有大量的异常不在本文的讨论范围之内,就不赘述了。至此,之前困扰我的疑团已经解开了。