Очень большая продолжительность маркировки Finalize на этапе Remark G1GC

Приложение перестает отвечать на запросы при высокой нагрузке, пока сборщик мусора 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] 

Сервер имеет 128 ГБ оперативной памяти

Параметры JVM, связанные с GC:

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

person Ivan Shramko    schedule 11.09.2015    source источник
comment
примечание -> Обработка SATB -> SATB записываются потоками-мутаторами. Так что, возможно, параллельная фаза не поспевает за мутаторами. Сколько ядер/потоков? Сколько выделено для GC (проверьте с -XX:+PrintFlagsFinal и найдите ConcGCThreads. Кроме того, ваши нормы распределения настолько высоки, что необходимо молодое поколение 10G?   -  person the8472    schedule 11.09.2015
comment
Простите за поздний ответ. Есть 32 ядра (с HyperThreading). -XX:+PrintFlagsFinal показывает 6 для ConcGCThreads   -  person Ivan Shramko    schedule 01.10.2015


Ответы (1)


AIUI Finalize Marking часть G1 в основном состоит из обработки буферов SATB, которые не могут быть обработаны на этапе параллельной маркировки.

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

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

person the8472    schedule 01.10.2015
comment
Спасибо за ответ. Вы хоть представляете, сколько потоков я должен выделить для GC? - person Ivan Shramko; 02.10.2015
comment
нет, просто попробуйте некоторые цифры, измерьте и посмотрите, насколько велика разница. - person the8472; 02.10.2015
comment
Пробовал увеличивать темы, не помогло. Я обновил исходный пост - person Ivan Shramko; 06.10.2015
comment
еще одна проверка работоспособности заключается в том, чтобы убедиться, что подкачки не происходит, хотя было бы странно, если бы она появлялась только в паузах примечаний и больше нигде. - person the8472; 07.10.2015
comment
Это не помогло. Паузы, видимо, стали короче из-за снижения нагрузки на сервер. Снова две паузы длительностью около 80 секунд - person Ivan Shramko; 12.10.2015
comment
Хм, я вижу [FinalReference, 100288 refs, 0.0330312 secs], здесь много отсылок, хотя сама обработка кажется быстрой. Посмотрите, имеет ли значение +ParallelRefProcEnabled. И, возможно, отследить, что использует эти финализаторы. - person the8472; 12.10.2015
comment
Я написал в список рассылки, о котором вы мне сказали, — hotspot-gc-use. У меня есть ответ, что проблема в Transparent_huge_pages в Linux. Я отключил его и посмотрю, поможет ли это. - person Ivan Shramko; 13.10.2015
comment
а, интересно. если это тоже не поможет, у меня нет идей. - person the8472; 13.10.2015