G1垃圾收集器长时间暂停不知道

Question

我正在尝试调整我的应用程序的响应性，最大允许的GC暂停是40毫秒。我不明白为什么这个暂停花了大约900毫秒的时间。应用程序是低延迟应用程序，旨在为高QPS提供服务。

GC参数：-Xmx5G -XX:+UseG1GC -XX:MaxGCPauseMillis=40

日志：

2014-10-02T16:31:08.508+0530: 2072.186: [GC pause (young)  
Desired survivor size 148373504 bytes, new threshold 15 (max 15)  
- age   1:   10600184 bytes,   10600184 total  
- age   2:      67024 bytes,   10667208 total  
- age   3:      44560 bytes,   10711768 total  
- age   4:       3520 bytes,   10715288 total  
- age   5:       4080 bytes,   10719368 total  
- age   6:       4464 bytes,   10723832 total  
- age   7:       2568 bytes,   10726400 total  
- age   8:       4872 bytes,   10731272 total  
- age   9:       3216 bytes,   10734488 total  
- age  10:       2400 bytes,   10736888 total  
- age  11:       2024 bytes,   10738912 total  
- age  12:       3144 bytes,   10742056 total  
- age  13:       8584 bytes,   10750640 total  
- age  14:       2672 bytes,   10753312 total  
- age  15:        696 bytes,   10754008 total  
, 0.0384210 secs]  
   [Parallel Time: 15.2 ms, GC Workers: 15]  
      [GC Worker Start (ms): Min: 2072186.5, Avg: 2072186.5, Max: 2072186.6, Diff: 0.1]  
      [Ext Root Scanning (ms): Min: 1.0, Avg: 1.0, Max: 1.1, Diff: 0.1, Sum: 15.2]  
      [Update RS (ms): Min: 0.3, Avg: 0.4, Max: 0.4, Diff: 0.1, Sum: 5.7]  
         [Processed Buffers: Min: 1, Avg: 3.3, Max: 5, Diff: 4, Sum: 49]  
      [Scan RS (ms): Min: 0.5, Avg: 0.5, Max: 0.6, Diff: 0.1, Sum: 7.8]  
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]  
      [Object Copy (ms): Min: 12.8, Avg: 12.9, Max: 13.0, Diff: 0.2, Sum: 193.0]  
      [Termination (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.7]  
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.1, Sum: 1.4]  
      [GC Worker Total (ms): Min: 14.9, Avg: 15.0, Max: 15.1, Diff: 0.2, Sum: 225.1]  
      [GC Worker End (ms): Min: 2072201.5, Avg: 2072201.5, Max: 2072201.6, Diff: 0.1]  
   [Code Root Fixup: 0.2 ms]  
   [Code Root Migration: 0.6 ms]  
   [Clear CT: 0.8 ms]  
   [Other: 21.6 ms]  
      [Choose CSet: 0.0 ms]  
      [Ref Proc: 14.2 ms]  
      [Ref Enq: 0.6 ms]  
      [Free CSet: 6.6 ms]  
   [Eden: 2244.0M(2244.0M)->0.0B(2571.0M) Survivors: 19.0M->10.0M Heap: 2443.7M(5120.0M)->191.4M(5120.0M)]  
 [Times: user=0.26 sys=0.00, real=0.90 secs]   
2014-10-02T16:31:09.406+0530: 2073.085: Total time for which application threads were stopped: 0.8992240 seconds  

java -version：

java版本"1.7.0_60“

Java(TM) SE运行时环境(内部版本号1.7.0_60-b19)

Java HotSpot(TM) 64位服务器虚拟机(内部版本24.60-b09，混合模式)

请帮我理解一下是什么导致了这么长时间的停顿？如何预防呢？

Answer 1

据我所知，该进程在gc期间被阻塞，这意味着它必须等待资源。

这一行告诉您执行时间：

[Times: user=0.26 sys=0.00, real=0.90 secs]

使用

• user表示纯cpu time.
• sys表示内核time.
• real表示真实时间。

java gc测得的时间低于40ms，请看这一行：

, 0.0384210 secs]  

在以下情况下，可能会出现此类阻塞：

系统上的网络、Disks)

• Another process正在执行IO繁重操作(例如，系统上的
• 正在对所需资源之一造成高负载

在您的情况下，我认为一定是其他原因占用了CPU时间，但很难说。

添加：

另一件可能发生的事情是，gc试图访问已经交换到磁盘的内存，导致长时间阻塞IO操作。我不知道这种可能性有多大，所以我可能完全错了。