神仙的仙居

最近在升级一个 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 内核参数来控制。