Незначительный GC и полный GC одновременно?

Вот фрагмент журнала GC, который показывает полное событие CMS GC:

2016-12-29T22:44:34.741-0500: 27572.982: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2508212K(23068672K)] 2931097K(26843584K), 0.0213349 secs] [Times: user=0.22 sys=0.00, real=0.02 secs] 
2016-12-29T22:44:34.763-0500: 27573.004: [CMS-concurrent-mark-start]
2016-12-29T22:44:36.013-0500: 27574.254: [CMS-concurrent-mark: 0.208/1.250 secs] [Times: user=3.07 sys=0.10, real=1.25 secs] 
2016-12-29T22:44:36.014-0500: 27574.255: [CMS-concurrent-preclean-start]
2016-12-29T22:44:36.061-0500: 27574.303: [CMS-concurrent-preclean: 0.047/0.048 secs] [Times: user=0.12 sys=0.00, real=0.05 secs] 
2016-12-29T22:44:36.062-0500: 27574.303: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2016-12-29T22:44:41.339-0500: 27579.580: [CMS-concurrent-abortable-preclean: 4.084/5.277 secs] [Times: user=9.53 sys=0.46, real=5.27 secs] 
2016-12-29T22:44:41.356-0500: 27579.598: [GC (CMS Final Remark) [YG occupancy: 3509179 K (3774912 K)]2016-12-29T22:44:41.357-0500: 27579.598: [Rescan (parallel) , 0.0816014 secs]2016-12-29T22:44:41.438-0500: 27579.680: [weak refs processing, 0.0000347 secs]2016-12-29T22:44:41.438-0500: 27579.680: [class unloading, 0.0292451 secs]2016-12-29T22:44:41.468-0500: 27579.709: [scrub symbol table, 0.0069857 secs]2016-12-29T22:44:41.475-0500: 27579.716: [scrub string table, 0.0010933 secs][1 CMS-remark: 2508212K(23068672K)] 6017391K(26843584K), 0.1194737 secs] [Times: user=2.18 sys=0.00, real=0.12 secs] 
2016-12-29T22:44:41.477-0500: 27579.718: [CMS-concurrent-sweep-start]
2016-12-29T22:44:41.618-0500: 27579.860: [GC (Allocation Failure) 2016-12-29T22:44:41.619-0500: 27579.860: [ParNew: 3579431K->419392K(3774912K), 5.7752364 secs] 6080306K->3302237K(26843584K), 5.7769753 secs] [Times: user=4.70 sys=8.50, real=5.78 secs] 
2016-12-29T22:44:47.698-0500: 27585.940: [CMS-concurrent-sweep: 0.230/6.221 secs] [Times: user=5.76 sys=8.55, real=6.22 secs] 
2016-12-29T22:44:47.699-0500: 27585.940: [CMS-concurrent-reset-start]
2016-12-29T22:44:47.717-0500: 27585.958: [GC (System.gc()) 2016-12-29T22:44:47.718-0500: 27585.959: [ParNew: 527384K->155025K(3774912K), 0.7351766 secs] 3405551K->3441841K(26843584K), 0.7366514 secs] [Times: user=5.61 sys=1.44, real=0.74 secs] 
2016-12-29T22:44:48.503-0500: 27586.744: [CMS-concurrent-reset: 0.049/0.804 secs] [Times: user=5.81 sys=1.45, real=0.81 secs]

Похоже, что во время работы CMS произошло незначительное событие GC:

2016-12-29T22:44:41.618-0500: 27579.860: [GC (Allocation Failure) 2016-12-29T22:44:41.619-0500: 27579.860: [ParNew: 3579431K->419392K(3774912K), 5.7752364 secs] 6080306K->3302237K(26843584K), 5.7769753 secs] [Times: user=4.70 sys=8.50, real=5.78 secs]

Это нормально? Блокирует ли дополнительный сборщик мусора полный сборщик мусора?

Может ли это объяснить очень высокое системное время, которое мы наблюдаем? (система = 8,55 с, система = 8,50 с)


java jvm garbage-collection concurrent-mark-sweep
person benji    schedule 30.12.2016    source источник

Ответы (3)


arrow_upward
1
arrow_downward

В вашем случае используемые алгоритмы GC: -

Parallel New для молодых + Concurrent Mark and Sweep (CMS) для старого поколения

Кажется, во время работы CMS произошло незначительное событие GC. Это нормально?
Да, ParNew и CMS могут работать параллельно.

Блокирует ли второстепенный GC полный GC?
Да, параллельная коллекция CMS "прервана" второстепенными коллекциями ParNew. Сборы Молодого Поколения могут происходить в любое время во время параллельного сбора Старого Поколения. В таком случае основная коллекция будет чередоваться с событиями Minor GC.

Может ли это объяснить очень высокое системное время, которое мы наблюдаем?
Вам нужно проверить частоту и продолжительность событий Stop-the-world в GC.

  1. Начальная отметка CMS
  2. CMS Заключительное замечание
  3. ParNew

Глядя на ваш журнал, я могу сделать вывод, что ваш Minor GC (ParNew) занимает слишком много времени для завершения.
5,7752364 с: время, которое потребовалось сборщику мусора, чтобы пометить и скопировать в реальном времени. объекты в служебной информации «Молодое поколение + связь» с коллектором ConcurrentMarkSweep

Хороший справочник по Java GC, который стоит прочитать .

person Amit Bhati    schedule 30.12.2016

arrow_upward
0
arrow_downward

Конечно, молодые коллекции могут возникать во время старых коллекций. Обычно это не является большой проблемой, но в случаях, когда фаза комментариев CMS непосредственно следует за молодой коллекцией (или наоборот, поэтому обе паузы являются остановкой мира), это может снизить производительность. CMS попытается избежать этого, рассчитав, когда произойдет следующий молодой сбор, но это только теория.

person Kevin Peters    schedule 30.12.2016

arrow_upward
0
arrow_downward

Это абсолютно нормально, если Young GC работает между фазами CMS. Выполнение молодой коллекции прямо перед начальной отметкой CMS или рекомендацией CMS может даже сократить паузы, связанные с остановкой мира, в крупных GC.

Что НЕ нормально, так это большое системное время (время ЦП, затрачиваемое ядром) при сборке мусора. Обычно этого не должно происходить, поскольку сборка мусора в основном выполняется в пользовательском пространстве.

Проверьте top, perf и т. д., чтобы выяснить, что вызывает увеличение системного времени. Обычно это связано с проблемами памяти: подкачка или дефрагментация прозрачных огромных страниц.

person apangin    schedule 30.12.2016