java - G1 gc 日志没有显示长时间 gc 暂停的线索

Question

我有一个分布式缓存应用程序(内存绑定(bind)，由于与集群中其他节点的交互而具有网络 I/O)在 JVM 1.7.0_51 中运行，带有 G1 垃圾收集器。这是 JVM 配置:

-server -Xms1G -Xmx3000M -XX:+UseG1GC -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -XX:+PrintHeapAtGC -XX:MaxGCPauseMillis=50  -Xloggc:$HAZELCAST_HOME/logs/gclog.txt -verbose:gc

At 2014-08-21T16:32:16.032, GC caused a long pause over 33 seconds (gc log snippet as below): 2014-08-21T16:32:16.032-0700: 798408.606: Total time for which application threads were stopped: 33.7010420 seconds

我深入研究了 gc 日志(以及应用程序日志)，但没有看到为什么会发生 33 秒长暂停的明确线索。有什么方法可以让 G1 转储更多详细信息以显示长时间暂停的原因(以及针对什么事件的长时间暂停的分割，例如用于扫描 RS 的 xxxms 等)。

我封闭了几分钟的 gc 日志。您是否在 GC 日志中看到任何问题以及是否需要 JVM gc 调整？非常感谢!

GC 日志

2014-08-21T16:24:47.996-0700: 797960.570: Total time for which application threads were stopped: 0.0005740 seconds
{Heap before GC invocations=4957 (full 0):
 garbage-first heap   total 1048576K, used 535899K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 275 young (281600K), 6 survivors (6144K)
 compacting perm gen  total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:25:35.830-0700: 798008.405: [GC pause (young)
Desired survivor size 15204352 bytes, new threshold 15 (max 15)
- age   1:    1490920 bytes,    1490920 total
- age   2:    1041336 bytes,    2532256 total
- age   3:    1462192 bytes,    3994448 total
- age   4:     669528 bytes,    4663976 total
- age   5:     600560 bytes,    5264536 total
, 0.0387690 secs]
   [Parallel Time: 36.9 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798008405.0, Avg: 798008405.0, Max: 798008405.0, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 5.1, Avg: 5.4, Max: 5.7, Diff: 0.6, Sum: 10.8]
      [Update RS (ms): Min: 6.3, Avg: 6.7, Max: 7.1, Diff: 0.8, Sum: 13.4]
         [Processed Buffers: Min: 5, Avg: 14.0, Max: 23, Diff: 18, Sum: 28]
      [Scan RS (ms): Min: 8.5, Avg: 9.3, Max: 10.0, Diff: 1.5, Sum: 18.5]
      [Object Copy (ms): Min: 15.4, Avg: 15.4, Max: 15.5, Diff: 0.1, Sum: 30.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 36.8, Avg: 36.8, Max: 36.8, Diff: 0.0, Sum: 73.6]
      [GC Worker End (ms): Min: 798008441.8, Avg: 798008441.8, Max: 798008441.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.7 ms]
   [Eden: 269.0M(224.0M)->0.0B(606.0M) Survivors: 6144.0K->8192.0K Heap: 523.3M(1024.0M)->255.8M(1024.0M)]
Heap after GC invocations=4958 (full 0):
 garbage-first heap   total 1048576K, used 261979K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 8 young (8192K), 8 survivors (8192K)
 compacting perm gen  total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.09 sys=0.00, real=0.03 secs]
2014-08-21T16:25:35.869-0700: 798008.444: Total time for which application threads were stopped: 0.0395820 seconds
2014-08-21T16:25:47.806-0700: 798020.380: Total time for which application threads were stopped: 0.0004770 seconds
2014-08-21T16:26:43.565-0700: 798076.139: Total time for which application threads were stopped: 0.0004730 seconds
2014-08-21T16:26:47.960-0700: 798080.535: Total time for which application threads were stopped: 0.0004790 seconds
2014-08-21T16:27:47.180-0700: 798139.754: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:27:47.474-0700: 798140.048: Total time for which application threads were stopped: 0.0004160 seconds
2014-08-21T16:28:13.565-0700: 798166.140: Total time for which application threads were stopped: 0.0006670 seconds
2014-08-21T16:28:43.565-0700: 798196.139: Total time for which application threads were stopped: 0.0004590 seconds
2014-08-21T16:28:47.880-0700: 798200.454: Total time for which application threads were stopped: 0.0004490 seconds
2014-08-21T16:29:12.924-0700: 798225.499: Total time for which application threads were stopped: 0.0004600 seconds
2014-08-21T16:29:12.925-0700: 798225.499: Total time for which application threads were stopped: 0.0001880 seconds
2014-08-21T16:29:12.925-0700: 798225.499: Total time for which application threads were stopped: 0.0002230 seconds
2014-08-21T16:29:12.928-0700: 798225.502: Total time for which application threads were stopped: 0.0011150 seconds
2014-08-21T16:29:12.932-0700: 798225.506: Total time for which application threads were stopped: 0.0011190 seconds
2014-08-21T16:29:13.565-0700: 798226.140: Total time for which application threads were stopped: 0.0005240 seconds
{Heap before GC invocations=4958 (full 0):
 garbage-first heap   total 1048576K, used 536411K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 276 young (282624K), 8 survivors (8192K)
 compacting perm gen  total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:29:16.945-0700: 798229.519: [GC pause (young)
Desired survivor size 14680064 bytes, new threshold 15 (max 15)
- age   1:    1751568 bytes,    1751568 total
- age   2:    1108160 bytes,    2859728 total
- age   3:     997960 bytes,    3857688 total
- age   4:    1449136 bytes,    5306824 total
- age   5:     662736 bytes,    5969560 total
- age   6:     595944 bytes,    6565504 total
, 0.0454900 secs]
   [Parallel Time: 43.6 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798229519.7, Avg: 798229519.7, Max: 798229519.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 5.0, Avg: 5.1, Max: 5.2, Diff: 0.2, Sum: 10.2]
      [Update RS (ms): Min: 4.7, Avg: 4.8, Max: 4.9, Diff: 0.2, Sum: 9.7]
         [Processed Buffers: Min: 7, Avg: 14.5, Max: 22, Diff: 15, Sum: 29]
      [Scan RS (ms): Min: 11.9, Avg: 12.0, Max: 12.0, Diff: 0.1, Sum: 23.9]
      [Object Copy (ms): Min: 21.6, Avg: 21.6, Max: 21.6, Diff: 0.1, Sum: 43.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 43.5, Avg: 43.5, Max: 43.5, Diff: 0.0, Sum: 87.1]
      [GC Worker End (ms): Min: 798229563.2, Avg: 798229563.2, Max: 798229563.2, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.7 ms]
   [Eden: 268.0M(210.0M)->0.0B(576.0M) Survivors: 8192.0K->9216.0K Heap: 523.8M(1024.0M)->257.3M(1024.0M)]
Heap after GC invocations=4959 (full 0):
 garbage-first heap   total 1048576K, used 263515K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 9 young (9216K), 9 survivors (9216K)
 compacting perm gen  total 20480K, used 16858K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe76ad8, 0x00000007fbe76c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.09 sys=0.00, real=0.04 secs]
2014-08-21T16:29:16.991-0700: 798229.565: Total time for which application threads were stopped: 0.0462520 seconds
2014-08-21T16:29:35.008-0700: 798247.583: Total time for which application threads were stopped: 0.0005370 seconds
2014-08-21T16:29:35.098-0700: 798247.673: Total time for which application threads were stopped: 0.0003950 seconds
2014-08-21T16:29:35.099-0700: 798247.673: Total time for which application threads were stopped: 0.0001400 seconds
2014-08-21T16:29:43.566-0700: 798256.140: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:29:47.791-0700: 798260.365: Total time for which application threads were stopped: 0.0004690 seconds
2014-08-21T16:30:33.232-0700: 798305.806: Total time for which application threads were stopped: 0.0025060 seconds
2014-08-21T16:30:34.233-0700: 798306.807: Total time for which application threads were stopped: 0.0006220 seconds
2014-08-21T16:31:12.342-0700: 798344.917: Total time for which application threads were stopped: 0.0013470 seconds
2014-08-21T16:31:17.500-0700: 798350.074: Total time for which application threads were stopped: 0.0005640 seconds
2014-08-21T16:31:17.501-0700: 798350.076: Total time for which application threads were stopped: 0.0002760 seconds
2014-08-21T16:31:38.506-0700: 798371.080: Total time for which application threads were stopped: 0.0013400 seconds
2014-08-21T16:32:16.032-0700: 798408.606: Total time for which application threads were stopped: 33.7010420 seconds
2014-08-21T16:32:56.183-0700: 798448.758: Total time for which application threads were stopped: 0.0120100 seconds
2014-08-21T16:32:56.185-0700: 798448.759: Total time for which application threads were stopped: 0.0006060 seconds
2014-08-21T16:32:56.201-0700: 798448.775: Total time for which application threads were stopped: 0.0014260 seconds
2014-08-21T16:32:56.203-0700: 798448.777: Total time for which application threads were stopped: 0.0006110 seconds
2014-08-21T16:32:56.204-0700: 798448.778: Total time for which application threads were stopped: 0.0004730 seconds
2014-08-21T16:33:16.026-0700: 798468.601: Total time for which application threads were stopped: 0.0021260 seconds
2014-08-21T16:33:50.414-0700: 798502.988: Total time for which application threads were stopped: 0.0014210 seconds
2014-08-21T16:34:47.479-0700: 798560.054: Total time for which application threads were stopped: 0.0015890 seconds
{Heap before GC invocations=4959 (full 0):
 garbage-first heap   total 1048576K, used 657755K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 394 young (403456K), 9 survivors (9216K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:35:19.033-0700: 798591.607: [GC pause (young)
Desired survivor size 5767168 bytes, new threshold 5 (max 15)
- age   1:    2254608 bytes,    2254608 total
- age   2:    1409360 bytes,    3663968 total
- age   3:    1058280 bytes,    4722248 total
- age   4:     987544 bytes,    5709792 total
- age   5:    1435864 bytes,    7145656 total
- age   6:     658560 bytes,    7804216 total
- age   7:     593592 bytes,    8397808 total
, 0.0751810 secs]
   [Parallel Time: 71.2 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798591607.4, Avg: 798591607.4, Max: 798591607.4, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 6.1, Avg: 6.4, Max: 6.8, Diff: 0.6, Sum: 12.9]
      [Update RS (ms): Min: 8.3, Avg: 8.8, Max: 9.3, Diff: 0.9, Sum: 17.6]
         [Processed Buffers: Min: 11, Avg: 16.0, Max: 21, Diff: 10, Sum: 32]
      [Scan RS (ms): Min: 13.6, Avg: 13.7, Max: 13.9, Diff: 0.3, Sum: 27.4]
      [Object Copy (ms): Min: 41.9, Avg: 41.9, Max: 41.9, Diff: 0.0, Sum: 83.8]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.2]
      [GC Worker Total (ms): Min: 71.0, Avg: 71.0, Max: 71.0, Diff: 0.0, Sum: 142.0]
      [GC Worker End (ms): Min: 798591678.4, Avg: 798591678.4, Max: 798591678.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.8 ms]
   [Other: 3.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 2.4 ms]
   [Eden: 385.0M(74.0M)->0.0B(73.0M) Survivors: 9216.0K->8192.0K Heap: 642.3M(1024.0M)->258.4M(1024.0M)]
Heap after GC invocations=4960 (full 0):
 garbage-first heap   total 1048576K, used 264569K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 8 young (8192K), 8 survivors (8192K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.16 sys=0.00, real=0.07 secs] 
2014-08-21T16:35:19.108-0700: 798591.682: Total time for which application threads were stopped: 0.0762870 seconds
2014-08-21T16:35:47.699-0700: 798620.273: Total time for which application threads were stopped: 0.0010630 seconds
{Heap before GC invocations=4960 (full 0):
 garbage-first heap   total 1048576K, used 339321K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 81 young (82944K), 8 survivors (8192K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:36:30.675-0700: 798663.249: [GC pause (young)
Desired survivor size 5767168 bytes, new threshold 4 (max 15)
- age   1:    2632352 bytes,    2632352 total
- age   2:    1093712 bytes,    3726064 total
- age   3:    1028456 bytes,    4754520 total
- age   4:    1044688 bytes,    5799208 total
- age   5:     977400 bytes,    6776608 total
, 0.0444430 secs]
   [Parallel Time: 43.2 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798663249.6, Avg: 798663249.6, Max: 798663249.7, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 5.0, Avg: 5.4, Max: 5.8, Diff: 0.8, Sum: 10.9]
      [Update RS (ms): Min: 5.8, Avg: 6.3, Max: 6.7, Diff: 0.9, Sum: 12.5]
         [Processed Buffers: Min: 11, Avg: 13.0, Max: 15, Diff: 4, Sum: 26]
      [Scan RS (ms): Min: 11.1, Avg: 11.1, Max: 11.1, Diff: 0.0, Sum: 22.2]
      [Object Copy (ms): Min: 20.3, Avg: 20.3, Max: 20.4, Diff: 0.1, Sum: 40.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 43.2, Avg: 43.2, Max: 43.2, Diff: 0.0, Sum: 86.4]
      [GC Worker End (ms): Min: 798663292.8, Avg: 798663292.8, Max: 798663292.8, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 73.0M(73.0M)->0.0B(100.0M) Survivors: 8192.0K->6144.0K Heap: 331.4M(1024.0M)->259.0M(1024.0M)]
Heap after GC invocations=4961 (full 0):
 garbage-first heap   total 1048576K, used 265216K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 6 young (6144K), 6 survivors (6144K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.10 sys=0.00, real=0.04 secs] 
2014-08-21T16:36:30.720-0700: 798663.294: Total time for which application threads were stopped: 0.0453210 seconds
2014-08-21T16:36:47.997-0700: 798680.572: Total time for which application threads were stopped: 0.0007030 seconds
2014-08-21T16:37:47.460-0700: 798740.034: Total time for which application threads were stopped: 0.0007800 seconds
2014-08-21T16:37:48.932-0700: 798741.506: Total time for which application threads were stopped: 0.0006490 seconds
{Heap before GC invocations=4961 (full 0):
 garbage-first heap   total 1048576K, used 367616K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 106 young (108544K), 6 survivors (6144K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:38:05.883-0700: 798758.457: [GC pause (young)
Desired survivor size 7340032 bytes, new threshold 15 (max 15)
- age   1:     535816 bytes,     535816 total
- age   2:    2490064 bytes,    3025880 total
- age   3:    1060536 bytes,    4086416 total
- age   4:    1024088 bytes,    5110504 total
, 0.0365490 secs]
   [Parallel Time: 35.5 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798758457.2, Avg: 798758457.2, Max: 798758457.3, Diff: 0.0]
      [Ext Root Scanning (ms): Min: 5.2, Avg: 6.4, Max: 7.6, Diff: 2.4, Sum: 12.8]
      [Update RS (ms): Min: 5.2, Avg: 6.5, Max: 7.7, Diff: 2.4, Sum: 12.9]
         [Processed Buffers: Min: 0, Avg: 12.0, Max: 24, Diff: 24, Sum: 24]
      [Scan RS (ms): Min: 8.6, Avg: 8.7, Max: 8.8, Diff: 0.2, Sum: 17.4]
      [Object Copy (ms): Min: 13.7, Avg: 13.8, Max: 13.9, Diff: 0.2, Sum: 27.7]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 35.4, Avg: 35.4, Max: 35.4, Diff: 0.0, Sum: 70.8]
      [GC Worker End (ms): Min: 798758492.6, Avg: 798758492.6, Max: 798758492.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 0.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.1 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 100.0M(100.0M)->0.0B(178.0M) Survivors: 6144.0K->7168.0K Heap: 359.0M(1024.0M)->259.5M(1024.0M)]
Heap after GC invocations=4962 (full 0):
 garbage-first heap   total 1048576K, used 265728K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 7 young (7168K), 7 survivors (7168K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.08 sys=0.00, real=0.04 secs] 
2014-08-21T16:38:05.920-0700: 798758.494: Total time for which application threads were stopped: 0.0375420 seconds
2014-08-21T16:38:26.099-0700: 798778.673: Total time for which application threads were stopped: 0.0010220 seconds
2014-08-21T16:38:47.342-0700: 798799.916: Total time for which application threads were stopped: 0.0036430 seconds
2014-08-21T16:39:47.317-0700: 798859.892: Total time for which application threads were stopped: 0.0008300 seconds
2014-08-21T16:39:56.099-0700: 798868.674: Total time for which application threads were stopped: 0.0006290 seconds
2014-08-21T16:40:47.760-0700: 798920.334: Total time for which application threads were stopped: 0.0006050 seconds
{Heap before GC invocations=4962 (full 0):
 garbage-first heap   total 1048576K, used 448000K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 185 young (189440K), 7 survivors (7168K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
2014-08-21T16:41:06.971-0700: 798939.546: [GC pause (young)
Desired survivor size 12582912 bytes, new threshold 15 (max 15)
- age   1:     660960 bytes,     660960 total
- age   2:     447312 bytes,    1108272 total
- age   3:    2380256 bytes,    3488528 total
- age   4:    1043336 bytes,    4531864 total
- age   5:    1019096 bytes,    5550960 total
, 0.0459440 secs]
   [Parallel Time: 43.9 ms, GC Workers: 2]
      [GC Worker Start (ms): Min: 798939545.8, Avg: 798939545.8, Max: 798939545.9, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 6.4, Avg: 6.4, Max: 6.4, Diff: 0.0, Sum: 12.8]
      [Update RS (ms): Min: 7.9, Avg: 9.3, Max: 10.6, Diff: 2.7, Sum: 18.5]
         [Processed Buffers: Min: 12, Avg: 14.0, Max: 16, Diff: 4, Sum: 28]
      [Scan RS (ms): Min: 7.5, Avg: 8.8, Max: 10.2, Diff: 2.8, Sum: 17.7]
      [Object Copy (ms): Min: 19.2, Avg: 19.3, Max: 19.3, Diff: 0.1, Sum: 38.5]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 43.7, Avg: 43.8, Max: 43.8, Diff: 0.1, Sum: 87.5]
      [GC Worker End (ms): Min: 798939589.6, Avg: 798939589.6, Max: 798939589.6, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.2 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.7 ms]
   [Eden: 178.0M(178.0M)->0.0B(193.0M) Survivors: 7168.0K->7168.0K Heap: 437.5M(1024.0M)->259.5M(1024.0M)]
Heap after GC invocations=4963 (full 0):
 garbage-first heap   total 1048576K, used 265728K [0x000000073f600000, 0x000000077f600000, 0x00000007fae00000)
  region size 1024K, 7 young (7168K), 7 survivors (7168K)
 compacting perm gen  total 20480K, used 16898K [0x00000007fae00000, 0x00000007fc200000, 0x0000000800000000)
   the space 20480K,  82% used [0x00000007fae00000, 0x00000007fbe80ab0, 0x00000007fbe80c00, 0x00000007fc200000)
No shared spaces configured.
}
 [Times: user=0.10 sys=0.00, real=0.05 secs] 
2014-08-21T16:41:07.018-0700: 798939.592: Total time for which application threads were stopped: 0.0471700 seconds
2014-08-21T16:41:47.416-0700: 798979.990: Total time for which application threads were stopped: 0.0006110 seconds
2014-08-21T16:42:26.100-0700: 799018.674: Total time for which application threads were stopped: 0.0008380 seconds
2014-08-21T16:42:47.463-0700: 799040.037: Total time for which application threads were stopped: 0.0008070 seconds
2014-08-21T16:43:26.100-0700: 799078.675: Total time for which application threads were stopped: 0.0009130 seconds
2014-08-21T16:43:47.648-0700: 799100.222: Total time for which application threads were stopped: 0.0006330 seconds
2014-08-21T16:43:48.700-0700: 799101.274: Total time for which application threads were stopped: 0.0006050 seconds
2014-08-21T16:44:18.539-0700: 799131.113: Total time for which application threads were stopped: 0.0006640 seconds

Answer 1

这与垃圾收集无关。根据日志，暂停发生在 GC 周期之外。

Total time for which application threads are stopped 消息在每个安全点后打印。由于操作系统卡住，通常可以看到非常长的安全点时间。这可能是因为磁盘 I/O 密集，或者当系统开始交换时，或者当另一个高优先级进程占用所有 CPU 时间时。要找出原因，请检查您的操作系统性能计数器。