java - G1GC Remark 阶段 Finalize marking 的持续时间非常长

Question

当 G1 垃圾收集器处于 Remark 阶段(完成标记)时，应用程序在高负载下变得无响应。这是 gc 日志的一部分(暂停发生在 2015-08-30T11:24:23.780):

2015-08-30T11:24:22.736-0400: 431394.465: [GC pause (GCLocker Initiated GC) (young) (initial-mark), 0.2050778 secs]
[Parallel Time: 156.7 ms, GC Workers: 23]
[GC Worker Start (ms): Min: 431394466.6, Avg: 431394466.8, Max: 431394466.9, Diff: 0.3]
  [Ext Root Scanning (ms): Min: 3.9, Avg: 4.3, Max: 8.5, Diff: 4.5, Sum: 99.2]
  [Update RS (ms): Min: 15.7, Avg: 20.0, Max: 20.5, Diff: 4.8, Sum: 460.5]
     [Processed Buffers: Min: 21, Avg: 31.3, Max: 54, Diff: 33, Sum: 719]
  [Scan RS (ms): Min: 56.4, Avg: 57.2, Max: 58.2, Diff: 1.8, Sum: 1314.9]
  [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
  [Object Copy (ms): Min: 72.9, Avg: 73.8, Max: 74.5, Diff: 1.6, Sum: 1698.3]
  [Termination (ms): Min: 0.4, Avg: 0.8, Max: 0.9, Diff: 0.5, Sum: 17.8]
     [Termination Attempts: Min: 1, Avg: 186.9, Max: 214, Diff: 213, Sum: 4298]
  [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.3]
  [GC Worker Total (ms): Min: 156.0, Avg: 156.2, Max: 156.3, Diff: 0.3, Sum: 3592.2]
  [GC Worker End (ms): Min: 431394622.9, Avg: 431394622.9, Max: 431394623.0, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 6.4 ms]
[Other: 41.8 ms]
  [Choose CSet: 0.0 ms]
  [Ref Proc: 27.2 ms]
  [Ref Enq: 1.2 ms]
  [Redirty Cards: 2.3 ms]
  [Humongous Register: 0.1 ms]
  [Humongous Reclaim: 0.1 ms]
  [Free CSet: 8.5 ms]
[Eden: 11.4G(11.4G)->0.0B(10.4G) Survivors: 736.0M->800.0M Heap: 56.6G(100.0G)->45.3G(100.0G)]
[Times: user=3.69 sys=0.08, real=0.21 secs] 
2015-08-30T11:24:22.951-0400: 431394.679: [GC concurrent-root-region-scan-start]
2015-08-30T11:24:23.101-0400: 431394.829: [GC concurrent-root-region-scan-end, 0.1499777 secs]
2015-08-30T11:24:23.101-0400: 431394.829: [GC concurrent-mark-start]
2015-08-30T11:24:23.779-0400: 431395.508: [GC concurrent-mark-end, 0.6781424 secs]
2015-08-30T11:24:23.780-0400: 431395.509: [GC remark 2015-08-30T11:24:23.780-0400: 431395.509: [Finalize Marking, 128.7675820 secs] 2015-08-30T11:26:32.548-0400: 431524.277: [GC ref-proc, 0.0246842 secs] 2015-08-30T11:26:32.573-0400: 431524.301: [Unloading, 0.0113214 secs], 128.8485361 secs]
[Times: user=2182.97 sys=753.23, real=128.83 secs] 
2015-08-30T11:26:32.631-0400: 431524.360: [GC cleanup 45G->45G(100G), 0.1537170 secs]
[Times: user=3.46 sys=0.00, real=0.16 secs] 
2015-08-30T11:26:32.785-0400: 431524.514: [GC concurrent-cleanup-start]
2015-08-30T11:26:32.785-0400: 431524.514: [GC concurrent-cleanup-end, 0.0000678 secs] 

服务器有 128GB 内存

GC 相关的 JVM 选项:

-XX:InitialHeapSize=107374182400 -XX:+ManagementServer -XX:MaxHeapSize=107374182400 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps -XX:+TieredCompilation -XX:+UseCondCardMark -XX:+UseG1GC

Java 版本:

Java version "1.8.0_60"
Java(TM) SE Runtime Environment (build 1.8.0_60-b27)
Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode)

任何想法可能是什么原因？

更新:我尝试设置 ParallelGCThreads=32 和 ConcGCThreads=8。暂停持续时间为 82 秒。变短了，但还是太长了

 {Heap before GC invocations=1558 (full 0):
     garbage-first heap   total 94371840K, used 83001550K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
      region size 32768K, 1234 young (40435712K), 58 survivors (1900544K)
     Metaspace       used 77160K, capacity 77951K, committed 78080K, reserved 79872K
     204611.028: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
    2015-10-04T15:00:05.197-0400: 204611.028: [GC pause (GCLocker Initiated GC) (young) (initial-mark)
    Desired survivor size 2600468480 bytes, new threshold 2 (max 2)
    - age   1:  621290376 bytes,  621290376 total
    - age   2:  245159208 bytes,  866449584 total
     204611.029: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 184157, predicted base time: 57.32 ms, remaining time: 142.68 ms, target pause time: 200.00 ms]
     204611.029: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1176 regions, survivors: 58 regions, predicted young region time: 131.19 ms]
     204611.029: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1176 regions, survivors: 58 regions, old: 0 regions, predicted pause time: 188.51 ms, target pause time: 200.00 ms]
    2015-10-04T15:00:05.416-0400: 204611.247: [SoftReference, 0 refs, 0.0023502 secs]2015-10-04T15:00:05.418-0400: 204611.249: [WeakReference, 394 refs, 0.0018755 secs]2015-10-04T15:00:05.420-0400: 204611.251: [FinalReference, 91704 refs, 0.
    0081225 secs]2015-10-04T15:00:05.428-0400: 204611.259: [PhantomReference, 29 refs, 1 refs, 0.0048953 secs]2015-10-04T15:00:05.433-0400: 204611.264: [JNI Weak Reference, 0.0000229 secs], 0.2600007 secs]
       [Parallel Time: 215.1 ms, GC Workers: 32]
          [GC Worker Start (ms): Min: 204611030.3, Avg: 204611030.5, Max: 204611030.6, Diff: 0.4]
          [Ext Root Scanning (ms): Min: 2.5, Avg: 3.2, Max: 8.3, Diff: 5.8, Sum: 103.2]
          [Update RS (ms): Min: 19.0, Avg: 24.5, Max: 35.3, Diff: 16.3, Sum: 782.9]
             [Processed Buffers: Min: 7, Avg: 23.7, Max: 31, Diff: 24, Sum: 758]
          [Scan RS (ms): Min: 40.4, Avg: 42.2, Max: 43.0, Diff: 2.6, Sum: 1349.0]
          [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
          [Object Copy (ms): Min: 131.5, Avg: 140.0, Max: 142.4, Diff: 10.9, Sum: 4480.1]
          [Termination (ms): Min: 1.9, Avg: 4.1, Max: 4.6, Diff: 2.7, Sum: 130.8]
             [Termination Attempts: Min: 262, Avg: 544.9, Max: 599, Diff: 337, Sum: 17437]
          [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 7.1]
          [GC Worker Total (ms): Min: 213.8, Avg: 214.2, Max: 214.5, Diff: 0.7, Sum: 6853.3]
          [GC Worker End (ms): Min: 204611244.4, Avg: 204611244.6, Max: 204611244.8, Diff: 0.4]
       [Code Root Fixup: 0.0 ms]
       [Code Root Purge: 0.0 ms]
       [Clear CT: 8.4 ms]
       [Other: 36.4 ms]
          [Choose CSet: 0.1 ms]
          [Ref Proc: 19.1 ms]
          [Ref Enq: 0.8 ms]
          [Redirty Cards: 2.0 ms]
          [Humongous Register: 0.0 ms]
          [Humongous Reclaim: 0.0 ms]
          [Free CSet: 11.5 ms]
       [Eden: 36.8G(36.7G)->0.0B(35.8G) Survivors: 1856.0M->1568.0M Heap: 79.2G(90.0G)->42.4G(90.0G)]
    Heap after GC invocations=1559 (full 0):
     garbage-first heap   total 94371840K, used 44456740K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
      region size 32768K, 49 young (1605632K), 49 survivors (1605632K)
     Metaspace       used 77160K, capacity 77951K, committed 78080K, reserved 79872K
    }
     [Times: user=7.11 sys=0.18, real=0.26 secs]
    2015-10-04T15:00:05.457-0400: 204611.288: [GC concurrent-root-region-scan-start]

    2015-10-04T15:00:05.457-0400: 204611.288: Total time for which application threads were stopped: 0.2607079 seconds, Stopping threads took: 0.0000623 seconds

    2015-10-04T15:00:05.593-0400: 204611.424: [GC concurrent-root-region-scan-end, 0.1359037 secs]

    2015-10-04T15:00:05.593-0400: 204611.424: [GC concurrent-mark-start]

    2015-10-04T15:00:06.238-0400: 204612.069: [GC concurrent-mark-end, 0.6448793 secs]

    2015-10-04T15:00:06.238-0400: 204612.069: [GC remark 2015-10-04T15:00:06.238-0400: 204612.069: [Finalize Marking, 82.5606577 secs] 2015-10-04T15:01:28.799-0400: 204694.630: [GC ref-proc2015-10-04T15:01:28.799-0400: 204694.630: [SoftRefer
    ence, 64 refs, 0.0031041 secs]2015-10-04T15:01:28.802-0400: 204694.633: [WeakReference, 383 refs, 0.0023197 secs]2015-10-04T15:01:28.805-0400: 204694.636: [FinalReference, 100288 refs, 0.0330312 secs]2015-10-04T15:01:28.838-0400: 204694.
    669: [PhantomReference, 2 refs, 37 refs, 0.0030514 secs]2015-10-04T15:01:28.841-0400: 204694.672: [JNI Weak Reference, 0.0000915 secs], 0.0539037 secs] 2015-10-04T15:01:28.853-0400: 204694.684: [Unloading, 0.0130054 secs], 82.6649201 sec
    s]
     [Times: user=1139.19 sys=393.93, real=82.65 secs]

    2015-10-04T15:01:28.903-0400: 204694.735: Total time for which application threads were stopped: 82.6655358 seconds, Stopping threads took: 0.0000918 seconds

    2015-10-04T15:01:28.904-0400: 204694.735: [GC cleanup 42G->42G(90G), 0.1166196 secs]

Answer 1

AIUI G1 的 Finalize Marking 部分主要包括处理在并发标记阶段无法处理的 SATB 缓冲区。

所以我的结论是 concurrent-mark 处理 SATB 缓冲区的速度不够快，无法跟上生成它们的增变器线程。

所以您可以尝试增加 ConcGCThreads 计数。请注意，这些线程将使用您的应用程序线程计算 CPU 时间。