最近在升级一个 java 应用时,在刚启动不久的时候发生了长时间的 gc,时间到了数秒,业务访问纷纷超时。
看了下 gc log:
2016-12-06T22:50:44.256+0800: 13.632: [GC pause (G1 Evacuation Pause) (young) Desired survivor size 13631488 bytes, new threshold 1 (max 15) - age 1: 27212320 bytes, 27212320 total 13.632: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 4890, predicted base time: 28.66 ms, remaining time: 71.34 ms, target pause time: 100.00 ms] 13.632: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 89 regions, survivors: 13 regions, predicted young region time: 6880.88 ms] 13.632: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 89 regions, survivors: 13 regions, old: 0 regions, predicted pause time: 6909.54 ms, target pause time: 100.00 ms] 22.969: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: recent GC overhead higher than threshold after GC, recent GC overhead: 65.85 %, threshold: 10.00 %, uncommitted: 0 bytes, calculated expansion amount: 0 bytes (20.00 %)] , 9.3374979 secs] ... [Object Copy (ms): 8821.5 6481.7 8743.0 6477.4 8173.8 6477.4 6477.5 6477.3 6792.5 6477.2 6477.0 6476.7 9331.9 9250.5 6476.0 6476.0 6471.3 7438.9 Min: 6471.3, Avg: 7211.0, Max: 9331.9, Diff: 2860.6, Sum: 129797.8] ...
这还是一次 young gc,说明 java 自身的堆是够用的,并没有升级为 mix。但是为什么用了这么长时间呢?注意到大部分时间都是花在了 Object Copy 上。内存 copy 哪怕是几个 G,都不可能花那么久。这里必有蹊跷。
搜索到的结果里,有提到内存不足,使用 swap 造成的情况。但是我们的内存是足够的,而且已经禁用了 swap。但是这倒是给了个提示。看了下当时的内存情况,有大量内存在 cache 中。于是想到了一种可能:有大量文件写入,使 page cache 填满了内存。而我们的 java 应用使用了 4G 的堆大小,刚启动的时候,大部分虚拟内存都还没有分配实际的物理内存。而在 java 在 gc 的过程中需要映射物理内存时,需要等待系统将这部分内存释放出来。如果这时候脏页的数量大,就需要等待脏页刷写到磁盘。一涉及 IO,时间就完全没谱了。
然后在测试环境试着重现一下,先用 dd 写几个大文件,直到剩余的空闲内存很少,大部分都在 cache 中,然后再次启动应用,果然重现了。临时处理办法就是在启动应用的时候,如果发现空闲内存不够,就先用 vmtouch 刷一下占用 cache 的文件缓存(通常是日志)。为了更好的避免类似情况发生,就要控制 page cache 里脏页数量,这样就算是需要释放 cache 也不会花多少时间。可以通过 vm.dirty_background_ratio
和 vm.dirty_ratio
内核参数来控制。