Когда G1 G C активирует начальную отметку помимо IHOP - PullRequest
Новая
       90

Когда G1 G C активирует начальную отметку помимо IHOP

1 голос
/ 30 января 2020

Я установил -XX: InitiatingHeapOccupancyPercent = 70 в JDK8 (без функции адаптивного IHOP), но я обнаружил, что есть две фазы начальной отметки в начале запуска JVM, когда HeapOccupancyPercent намного меньше 70%, есть ли другой фактор которая вызовет G1 G C начальная фаза метки? Заранее спасибо!

Выдержка из G C log:

2020-01-22T03: 58: 14.227 + 0000: 3.158: [G C пауза (Метаданные G C Порог) (молодой) (начальная отметка), 0,1583711 с] [Eden: 1056,0M (81920,0M) -> 0,0B (81184,0M) Выжившие: 0,0B-> 736,0M Куча: 1472,0M ( 160.0G) -> 1179.5M (160.0G)]

2020-01-22T04: 13: 07.073 + 0000: 896.004: [G C пауза (G1 Evacuation Pause) (молодой) (начальная отметка ), 3,8512514 с] [Eden: 81184,0M (81184,0M) -> 0,0B (71904,0M) Выжившие: 736,0M-> 10016,0M Куча: 83643,5M (160,0G) -> 11744,0M (160,0G)]

Версия JDK:

версия openjdk "1.8.0_222"

Среда выполнения OpenJDK (сборка 1.8.0_222-b10)

OpenJDK 64 -Bit Server VM (сборка 25.222-b10, смешанный режим)

Спасибо

****** Обновление 2020/02/01 G C log ****** ******

2020-01-22T03: 58: 14.227 + 0000: 3.158: [G C пауза (метаданные G C порог) (молодые) (начальная отметка ), 0,1583711 с]

[Параллельный Тим e: 143,8 мс, G C Рабочие: 33] 

 [GC Worker Start (ms): Min: 3158.7, Avg: 3159.4, Max: 3159.8, Diff: 1.1]

 [Ext Root Scanning (ms): Min: 0.6, Avg: 1.1, Max: 2.7, Diff: 2.1, Sum: 35.9]

 [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]

    [Processed Buffers: Min: 0, Avg: 0.1, Max: 2, Diff: 2, Sum: 4]

 [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]

 [Code Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 5.9, Diff: 5.9, Sum: 8.5]

 [Object Copy (ms): Min: 135.7, Avg: 141.1, Max: 141.5, Diff: 5.9, Sum: 4654.7]

 [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.7]

    [Termination Attempts: Min: 1, Avg: 9.1, Max: 15, Diff: 14, Sum: 301]

 [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.9]

 [GC Worker Total (ms): Min: 142.0, Avg: 142.5, Max: 143.1, Diff: 1.1, Sum: 4701.0]

 [GC Worker End (ms): Min: 3301.8, Avg: 3301.9, Max: 3301.9, Diff: 0.1]

[Код Root Исправление: 0,1 мс]

[Код Root Продувка: 0,0 мс]

[Исправление дедупликации строки: 0,9 мс, G C Рабочие: 33] 

 [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

 [Table Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.7, Diff: 0.7, Sum: 0.7]

[Очистить CT: 0,4 мс]

[Другие: 13,1 мс] 

 [Choose CSet: 0.0 ms]

 [Ref Proc: 9.4 ms]

 [Ref Enq: 0.9 ms]

 [Redirty Cards: 0.6 ms]

 [Humongous Register: 0.2 ms]

 [Humongous Reclaim: 0.0 ms]

 [Free CSet: 0.1 ms]

[Eden: 1056.0M (81920.0M) -> 0.0B (81184.0M) Выжившие: 0.0B-> 736.0M Кучи: 1472.0M (160.0G) -> 1179.5M (160.0G)]

[Время: пользователь = 1,77 сис = 2,98, реальное = 0,15 с]

2020-01-22T03: 58: 14,386 + 0000: 3,316: [G C одновременный - root -region-Scan-Start]

2020-01-22T03: 58: 14.458 + 0000: 3.388: [G C одновременная отметка-запуск]

2020-01-22T03: 58: 14.458 + 0000: 3.388: [G C одновременный- root -обзор конца сканирования, 0,0718879 с]

2020-01-22T03: 58: 14,485 + 0000: 3,416: [G C примечание 2020-01-22T03: 58: 14,485 + 0000: 3.416: [Завершить маркировку, 0,0011542 с] 2020-01-22T03: 58: 14,486 + 0000: 3,417: [G C ref-pro c , 0,0072547 с] 2020-01-22T03: 58: 14,494 + 0000: 3,424: [Разгрузка, 0,0050159 с], 0,015 1448 секунд]

[Время: пользователь = 0,19 сис = 0,02, реальное = 0,02 с]

2020-01-22T03: 58: 14.485 + 0000: 3.415: [G C одновременный -марка, 0,0271495 с]

2020-01-22T03: 58: 14,500 + 0000: 3,431: [G C очистка 1259М-> 1259М (160G), 0,0033890 с]

[Время: пользователь = 0,06 сис = 0,00, реальное = 0,00 с]

2020-01-22T04: 13: 07,073 + 0000: 896,004: [G C пауза (G1 Evacuation Pause) (молодой) (начальная отметка), 3,8512514 с]

[Параллельное время: 3822,9 мс, G C Рабочие: 33] 

 [GC Worker Start (ms): Min: 896005.5, Avg: 896006.2, Max: 896006.6, Diff: 1.1]

 [Ext Root Scanning (ms): Min: 4.3, Avg: 5.3, Max: 8.4, Diff: 4.1, Sum: 175.2]

 [Update RS (ms): Min: 0.0, Avg: 0.2, Max: 0.8, Diff: 0.8, Sum: 7.6]

    [Processed Buffers: Min: 0, Avg: 1.3, Max: 6, Diff: 6, Sum: 44]

 [Scan RS (ms): Min: 2254.9, Avg: 2266.4, Max: 2268.2, Diff: 13.3, Sum: 74790.0]

 [Code Root Scanning (ms): Min: 0.0, Avg: 0.7, Max: 10.4, Diff: 10.4, Sum: 23.8]

 [Object Copy (ms): Min: 1535.2, Avg: 1537.7, Max: 1548.1, Diff: 13.0, Sum: 50745.7]

 [Termination (ms): Min: 0.0, Avg: 11.2, Max: 13.3, Diff: 13.2, Sum: 368.0]

    [Termination Attempts: Min: 1, Avg: 2270.1, Max: 2464, Diff: 2463, Sum: 74914]

 [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 8.1]

 [GC Worker Total (ms): Min: 3821.2, Avg: 3821.8, Max: 3822.5, Diff: 1.3, Sum: 126118.4]

 [GC Worker End (ms): Min: 899827.7, Avg: 899827.9, Max: 899828.2, Diff: 0.5]

[Код Root Исправление: 0,5 мс]

[Код Root Очистка: 0,1 мс]

[Исправление дедупликации строки: 1,1 мс, G C Рабочие: 33] 

 [Queue Fixup (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]

 [Table Fixup (ms): Min: 0.0, Avg: 0.1, Max: 1.0, Diff: 1.0, Sum: 1.9]

[Очистить CT: 4,7 мс]

[Другое: 21,9 мс] 

 [Choose CSet: 0.0 ms]

 [Ref Proc: 8.5 ms]

 [Ref Enq: 0.9 ms]

 [Redirty Cards: 4.1 ms]

 [Humongous Register: 0.2 ms]

 [Humongous Reclaim: 0.0 ms]

 [Free CSet: 6.2 ms]

[Eden: 81184,0M (81184,0M) -> 0,0B (71904,0M) Выжившие: 736,0M-> 10016,0M Heap : 83643,5M (160,0G) -> 11744,0M (160,0G)]

[Время: пользователь = 50,77 сис = 10,33, реальное = 3,85 с]

1 Ответ

0 голосов
/ 31 января 2020

Ну, один из них очевиден, и он имеет отношение к Metaspace, , вот более подробно об этом . Я имею в виду, когда срабатывает Full G C, начальная фаза - mark.

Мне известны 3 других случая, когда фаза метки (см. Ниже) запускается: 

 1) IHOP is reached
 2) G1ReservePercent is reached
 3) a humongous allocation happens

Что происходит после фазы метки, зависит от нескольких параметров, например mixed GCs будет зависеть от G1HeapWastePercent параметра; но в любом случае young GC будет срабатывать после mark phase в любом случае .

Первая точка заключается в том, что огромное распределение может начать параллельный цикл, вы можете проанализировать себя , если и когда это произойдет что.

Второй пункт (из ваших комментариев): я говорил, что в общем , то есть причина для запуска фазы одновременной отметки, а не для ваш случай указан c.

Но давайте посмотрим на ваш журнал (я слегка отформатировал его): 

[GC pause (G1 Evacuation Pause) (young) (initial-mark), 3.8512514 secs]    
    [  Eden: 81184.0M(81184.0M)->0.0B(71904.0M) 
       Survivors: 736.0M->10016.0M 
       Heap: 83643.5M(160.0G)->11744.0M(160.0G)
    ]

Это показывает несколько вещей. Ваш eden 80GB, 70GB из которых где мертвые объекты. Таким образом, Eden было уменьшено до 71904.0M, а Survivor увеличено до 10016 M. Поскольку вы установили InitiatingHeapOccupancyPercent = 70, этого никогда не произойдет, если Eden такой большой, это значение никогда не достигнет 70%. Подумайте об этом, вы говорите: «начать этап маркировки, когда я нахожусь в 70% от общей кучи в старом поколении»; но ваш eden составляет 50% от кучи ... Это было лишь незначительное наблюдение.

Что касается , почему это срабатывает - это очевидно: ваш eden был полон (81184.0M(81184.0M)). КАК почему initial-mark также ? Это всегда вызвано как часть молодой коллекции.

Третий пункт

Я не уверен, что понимаю, что вы имеете в виду. В журналах четко сказано, что initial-mark, то есть STW event, что делает young GC.

...