Очень длинная длительность маркировки завершения на этапе замещения G1GC

Question

Приложение становится невосприимчивым к высокой нагрузке, а сборщик мусора G1 находится на этапе «Замечание» (отметка «Финализация»). Это является частью журнала гх (пауза произошло в 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-связанные параметры виртуальной машины Java:

-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) 

Любые идеи, что может быть причиной?

UPDATE: Я попытался установить 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 Finalize Marking часть G1 в основном состоит из обработки SATB буферов, которые не могут быть обработаны в процессе одновременной маркировки фазы.

Таким образом, мой вывод состоит в том, что concurrent-mark не обрабатывает буферы SATB достаточно быстро, чтобы не отставать от потоков мутаторов, генерирующих их.

Так что вы можете попробовать увеличить счет ConcGCThreads. Обратите внимание, что эти потоки будут вычислять время процессора с вашими приложениями.