Санкт-Петербургская группа тестирования JVM

Сборщик мусора Concurrent Mark-Sweep (CMS)

В предыдущих статьях мы рассказывали о последовательном сборщике мусора (SerialGC). Напомню, что этот сборщик мусора использует так называемый stop-the-world режим работы, при котором на время очистки памяти все потоки приложения должны быть приостановлены. Также, надеюсь, вы помните, что на сегодняшний день все сборщики в HotSpot JVM делят память на две области (на два поколения): YoungGen и OldGen. Как правило, сборки мусора в YoungGen происходят очень быстро и практически незаметны для приложения, тогда как очистка более большой по размеру области OldGen может потребовать значительного времени, в течении которого потоки приложения будут бездействовать, то есть программа с точки зрения пользователя как бы «зависнет». Многие приложения очень чувствительны к таким остановкам в работе, и для них очень важно минимизировать stop-the-world паузы. Сегодня мы расскажем о сборщике мусора, призванном решить эту проблему — Concurrent Mark Sweep GC (CMS).

CMS также называют Mostly Concurrent Low Pause Collector. Слова в названии «mostly concurrent» (в большинстве случаев одновременный) значат, что этот сборщик мусора бóльшую часть работы может исполнять одновременно с выполнением приложения, и при его использовании не требуются длительные stop-the-world паузы.

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

Цикл сборки мусора CMS состоит из нескольких этапов, основные этапы следующие:

• начальная маркировка (initial mark): работа CMS начинается с очень короткой stop-the-world паузы, в течении которой сборщик мусора находит так называемые корневые (root) ссылки на объекты, созданные приложением (корневые ссылки это, например, ссылки, сохранённые в регистрах или в стеках потоков приложения).
• одновременная маркировка (concurrent mark): во время этого этапа CMS отмечает все объекты, достижимые из корневых объектов, то есть все «живые» объекты, которые не должны удаляться сборщиком мусора. Этот этап выполняется одновременно с работой приложения.
• повторная маркировка (remark): так как во время этапа одновременной маркировки потоки приложения продолжали работать, и в это время они могли создавать новые объекты и модифицировать ссылки, то к концу этого этапа нет гарантии, что все живые объекты были отмечены. Чтобы решить эту проблему CMS ещё раз приостанавливает приложение и завершает маркировку, проверяя все объекты, которые были изменены пользовательскими потоками во время выполнения предыдущего этапа. Поскольку повторная маркировка может занимать довольно много времени, то на многопроцессорных машинах этот этап выполняется несколькими параллельными потоками.
• одновременная очистка (concurrent sweep): после завершения этапа повторной маркировки все живые объекты в приложении были отмечены, и во время этапа одновременной очистки CMS удаляет весь найденный мусор (все неотмеченные объекты). Этот этап не требует приостановки приложения.

Таким образом, CMS разделяет всю работу по очистке OldGen на несколько частей, некоторые из которых могут выполняться одновременно с работой приложения, и за счёт этого избегает продолжительных stop-the-world пауз. В то же время из-за особенностей алгоритма общее количество работы, выполняемое CMS, становится больше по сравнению с последовательным сборщиком мусора (например, из-за необходимости повторной маркировки), и в результате этого при использовании CMS общая производительность приложения может несколько уменьшиться. Вот рисунок, демонстрирующий различия в работе CMS и последовательного сборщика мусора:

Различия в работе CMS и SerialGC

Стоит попробовать использовать CMS, если ваше приложение чувствительно к длительным паузам, возникающим из-за работы сборщика мусора. Однако у CMS есть несколько особенностей, о которых надо знать при его использовании и, возможно, чтобы добиться хороших результатов c CMS, придётся потратить некоторое время на его настройку. Во-первых, надо помнить, что CMS работает одновременно с приложением, то есть приложению придётся делить с CMS ресурсы процессора. Поэтому лучших результатов при использовании CMS удастся добиться на машине с двумя и более процессорами. Во-вторых, CMS при сборке мусора не уплотняет (compact) OldGen. Последовательный сборщик мусора после очистки памяти перемещает все живые объекты в начало OldGen, в результате чего свободная память после очистки представляет собой непрерывную область. Это помогает избежать фрагментации, а также позволяет для выделения памяти в OldGen использовать очень быстрый алгоритм bump-the-pointer (для хранения адреса начала свободной памяти используется специальный указатель, и при выделении памяти к этому указателю просто прибавляется размер выделенной области). CMS в целях экономии времени не выполняет уплотнение, и после очистки OldGen свободная память не является одной непрерывной областью. В связи с этим сборщик мусора должен поддерживать специальные списки, хранящие адреса участков свободной памяти (free lists). При создании нового объекта сборщик мусора должен обойти эти списки, чтобы найти достаточно большую свободную область. Таким образом, при использовании CMS создание объекта это более дорогая операция. Также отсутствие уплотнения может вызвать фрагментацию памяти, и в случае, если CMS не может найти достаточно большой непрерывный участок свободной памяти для создания нового объекта, то он вынужден прервать одновременный (concurrent) режим работы, приостановить приложение и очистить память, используя тот же алгоритм (mark-sweep-compact), что и последовательный сборщик мусора.

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

Тестовое приложение (TestGCPause.java) запускает два потока, обменивающиеся сообщениями с использованием методов wait/notify. При этом измеряется пауза между вызовом notify и пробуждением потока, ждущего этот вызов (в реальном приложении это, например, могла бы быть пауза между нажатием на кнопку и моментом реакции приложения на это нажатие). В конце работы выводится максимальное значение паузы. В реальных Java приложениях, как правило, присутствуют долгоживущие объектов, не удаляемые сборщиком мусора, а также постоянно создаются временные объекты с коротким временем жизни. Попробуем сымитировать такое поведение. В начале работы заполним половину доступной памяти объектами, которые не будут удаляться на всём протяжении работы, и запустим поток, постоянно создающий короткоживущие объекты, провоцируя работу сборщика мусора (без этого потока, то есть если на работу приложения не влияет сборщик мусора, пауза, измеряемая приложением, не превышает 1 миллисекунду).

Для запуска приложения будем использовать машину с 1GB памяти и двумя процессорами AMD Opteron 246 с частотой 2.0 GHz под управлением RedHat Linux. JDK возьмём последний — 6u10.

Попробуем запустить это приложение с последовательным сборщиком мусора (используем флаг UseSerialGC):

$ java -XX:+UseSerialGC TestGCPause

Получим следующий результат:

Max pause: 130ms

Максимальная пауза между вызовом notify и пробуждением потока составила 130 миллисекунд, довольно маленькое значение.

При запуске виртуальной машины с размером кучи (heap), задаваемым по умолчанию (64Mb), сборка OldGen занимает практически столько же времени, что и сборка YoungGen (около 100 миллисекунд), поэтому для приложений, использующих маленькую кучу нет смысла применять CMS.

Увеличим размер кучи до 512Mb (флаг Xmx):

$ java -Xmx512M -XX:+UseSerialGC TestGCPause
Max pause: 2845ms

В этом случае максимальная пауза сооставляет почти 3 секунды, а это остановка в работе приложения, которую можно заметить невооружённым глазом.

Посмотрим, как ведёт себя сборщик мусора, используя флаг виртуальной машины PrintGCDetails (подробное описание вывода ВМ при использовании этого флага читайте здесь). VM во время работы приложения выводит следующее:

[GC [DefNew: 32256K->4031K(36288K), 0.2545190 secs] 314081K->312045K(520256K), 0.2545680 secs] [Times: user=0.24 sys=0.01, real=0.25 secs] 
[GC [DefNew: 36287K->4032K(36288K), 0.2001470 secs] 344301K->331816K(520256K), 0.2001950 secs] [Times: user=0.20 sys=0.00, real=0.21 secs]
[GC [DefNew: 36288K->4031K(36288K), 0.2605490 secs] 364072K->358486K(520256K), 0.2605980 secs] [Times: user=0.26 sys=0.00, real=0.27 secs] 
... 
[GC [DefNew: 36288K->4032K(36288K), 0.2079360 secs] 483936K->471620K(520256K), 0.2079850 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 

[GC [DefNew: 36288K->36288K(36288K), 0.0000400 secs][Tenured: 467588K->288524K(483968K), 2.7921040 secs] 503876K->288524K(520256K), 
[Perm : 29K->29K(12288K)], 2.7922500 secs] [Times: user=2.52 sys=0.27, real=2.79 secs] 

[GC [DefNew: 32256K->4032K(36288K), 0.2018780 secs] 320780K->312553K(520256K), 0.2019270 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 
...
[GC [DefNew: 36288K->4032K(36288K), 0.2704330 secs] 485862K->480611K(520256K), 0.2704820 secs] [Times: user=0.27 sys=0.00, real=0.27 secs] 

[GC [DefNew: 36288K->36288K(36288K), 0.0000400 secs][Tenured: 476579K->282332K(483968K), 2.7500490 secs] 512867K->282332K(520256K), 
[Perm : 29K->29K(12288K)], 2.7501810 secs] [Times: user=2.45 sys=0.29, real=2.75 secs]

[GC [DefNew: 32256K->4031K(36288K), 0.2577620 secs] 314588K->313060K(520256K), 0.2578110 secs] [Times: user=0.26 sys=0.00, real=0.25 secs] 
...

[GC [DefNew: 36288K->36288K(36288K), 0.0000510 secs][Tenured: 471923K->289031K(483968K), 2.8128280 secs] 508211K->289031K(520256K), 
[Perm : 29K->29K(12288K)], 2.8129710 secs] [Times: user=2.51 sys=0.28, real=2.80 secs] 

Строки, не выделенные жирным шрифтом, это сообщения о сборках мусора в YoungGen, в конце строки выводится время, затраченное на сборку мусора (real=0.25 secs). Как мы видим, YoungGen очищается быстро, примерно за 200–300 миллисекунд. Однако на протяжении работы приложения периодически переполняется OldGen, и происходят более длительные очистки этой области (сообщения о них выделены жирным шрифтом), занимающие около трёх секунд. И именно эти паузы, вызванные сборкой мусора, заметило наше тестовое приложение.

Поможет ли сборщик мусора CMS избавиться от этих длительных пауз?

Запустим приложение с CMS (флаг UseConcMarkSweepGC). Как я говорил, по умолчанию CMS для сборки мусора в YoungGen использует несколько параллельных потоков, но для того, чтобы сравнение с последовательным сборщиком было честным, отключим эту возможность. Для этого укажем флаг -UseParNewGC, и теперь YoungGen собирается также, как и при использовании SerialGC.

$ java -Xmx512M -XX:+UseConcMarkSweepGC -XX:-UseParNewGC TestGCPause

И что же мы получаем:

Max pause: 4170ms

Результат не улучшился, а стал хуже!

Попробуем разобраться, в чём тут дело. Опять используем флаг PrintGCDetails и проанализируем вывод:

[GC [DefNew: 14784K->⁞1600K(14784K), 0.1702280 secs] 314597K->310840K(522688K), 0.1702980 secs] [Times: user=0.17 sys=0.00, real=0.17 secs] 
[GC [DefNew: 14784K->1600K(14784K), 0.1705240 secs] 324024K->320559K(522688K), 0.1705890 secs] [Times: user=0.17 sys=0.00, real=0.16 secs] 

[GC [1 CMS-initial-mark: 318959K(507904K)] 322213K(522688K), 0.0104220 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 

[GC [DefNew: 14784K->1600K(14784K), 0.1843520 secs] 333743K->330570K(522688K), 0.1844180 secs] [Times: user=0.18 sys=0.00, real=0.19 secs]

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

Цифры «318959K(507904K)» — это размер занятой памяти в OldGen и полный размер этой области на момент запуска CMS. Интересной особенностью CMS является то, что сборку мусора в OldGen он, в отличие от других сборщиков, начинает не тогда, когда эта область памяти переполняется, а когда размер свободного места в ней становится ниже значения, задаваемого параметром CMSInitiatingOccupancyFraction (по умолчанию он равен 68%). Также из вывода ВМ видно, что работа CMS периодически прерывается сборками мусора в YoungGen, но это не мешает его работе.

После начальной маркировки запустился этап одновременной маркировки (concurrent mark), который закончился позже:

[GC [DefNew: 14784K->1600K(14784K), 0.1843520 secs] 333743K->330570K(522688K), 0.1844180 secs] [Times: user=0.18 sys=0.00, real=0.19 secs] 
...
...
[GC [DefNew: 14784K->1599K(14784K), 0.1994250 secs] 364654K->362358K(522688K), 0.1994900 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 

[CMS-concurrent-mark: 1.325/2.098 secs] [Times: user=2.43 sys=0.97, real=2.09 secs] 

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

[GC [DefNew: 14783K->1600K(14784K), 0.2067050 secs] 375542K->373539K(522688K), 0.2067690 secs] [Times: user=0.20 sys=0.00, real=0.20 secs] 
...
...
[GC [DefNew: 14784K->1600K(14784K), 0.0198450 secs] 422948K->410091K(522688K), 0.0199100 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 

[CMS-concurrent-preclean: 0.935/2.019 secs] [Times: user=2.30 sys=0.66, real=2.02 secs] 

[GC[YG occupancy: 1875 K (14784 K)][Rescan (non-parallel) [grey object rescan, 0.0021880 secs][root rescan, 0.0064850 secs], 0.0087500 secs]
[weak refs processing, 0.0000480 secs] [1 CMS-remark: 408491K(507904K)] 410367K(522688K), 0.0088710 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

После одновременной маркировка был выполнен этап, который ранее не был упомянут – concurrent preclean. Во время этого этапа выполняется часть работы, относящаяся к повторной маркировке (remark), но эта часть работы не требует приостановки приложения.

Затем был выполнен этап, требующий stop-the-world паузы: повторная маркировка (root rescan) и обработка слабых ссылок. В данном случае этот этап занял менее 1 миллисекунды.

[GC [DefNew: 14784K->1599K(14784K), 0.2332090 secs] 423275K->423303K(522688K), 0.2332690 secs] [Times: user=0.23 sys=0.00, real=0.23 secs]...
...

[CMS-concurrent-sweep: 1.559/2.838 secs] [Times: user=3.38 sys=0.90, real=2.83 secs]

[CMS-concurrent-reset: 0.011/0.011 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 

Завершают цикл сборки мусора этапы очистки (concurrent sweep) и ещё один не упоминавшийся этап – concurrent reset. Во время этапа concurrent reset CMS заново инициализирует свои внутренние структуры, и после завершения этого этапа CMS готов начать следующий цикл сборки.

Этот вывод демонстрирует «нормальный» режим работы CMS, при котором на самом деле не возникает больших пауз в работе приложения. Однако в выводе, полученном с PrintGCDetails можно увидеть и такие сообщения:

[GC [DefNew: 14783K->14783K(14784K), 0.0000450 secs][CMS[CMS-concurrent-preclean: 0.240/0.249 secs] [Times: user=0.26 sys=0.07, real=0.25 secs] 
(concurrent mode failure): 502848K->264540K(507904K), 3.6064830 secs] 517632K->264540K(522688K), [CMS Perm : 1856K->1856K(12288K)], 3.6066440 secs] [Times: user=3.33 sys=0.28, real=3.60 secs] 

Сообщение о сборке мусора в YoungGen содержит слова «concurrent mode failure». Что это значит? Когда происходит очистка YoungGen, то достаточно старые объекты (то есть объекты из YoungGen, пережившие несколько сборок мусора) перемещаются из YoungGen в OldGen. Понятно, что в OldGen должно быть достаточно свободного места, чтобы вместить эти объекты. При использовании CMS в начале сборки мусора в YoungGen проверяется количество свободной памяти в OldGen. Сборщик мусора пытается предсказать, сколько места может понадобиться, для этого он хранит среднее значение памяти, которое требовалось для перемещения объектов из YoungGen во время предыдущих сборок. Если перед началом сборки мусора в YoungGen памяти в OldGen недостаточно, то нормальная работа CMS прерывается и производится сборка мусора в обоих OldGen и YoungGen в stop-the-world режиме. Сообщение «concurrent mode failure» говорит о возникновении такой ситуации. И из этого сообщения видно, что полная сборка мусора потребовала 3.6 секунды.

Возможна и такая ситуация, что сборщик мусора решит, что памяти в OldGen достаточно и начнёт сборку в YoungGen, но в ходе этой сборки выяснится, что для перемещаемых объектов всё-таки не хватает места (например, из-за фрагментации OldGen). В этом случае сборка в YoungGen прекращается, и, как и в предыдущем случае, OldGen и YoungGen очищаются в stop-the-world режиме. При возникновении такой ситуации выводится сообщение «promotion failed»:

[GC [DefNew (promotion failed): 14783K->14783K(14784K), 0.3410700 secs][CMS[CMS-concurrent-preclean: 1.454/3.451 secs] [Times: user=3.68 sys=0.90, real=3.46 secs] 
(concurrent mode failure): 456925K->270357K(507904K), 3.8145030 secs] 458916K->270357K(522688K), [CMS Perm : 1856K->1856K(12288K)], 4.1556800 secs] [Times: user=3.82 sys=0.32, real=4.15 secs] 

Получается, что если CMS не успевает очищать OldGen достаточно быстро для того, чтобы эта область могла вместить объекты, перемещаемые в результате очистки YoungGen, то работа приложения всё равно будет периодически прерываться длительными stop-the-world паузами, от которых мы хотели избавиться.

Для того чтобы избежать подобных «сбоев» в работе CMS надо попытаться сделать так, чтобы в OldGen было всегда достаточно памяти для перемещаемых из YoungGen объектов. Для этого есть два простых способа: уменьшить размер YoungGen, в этом случае для перемещения объектов из этой области памяти в OldGen будет требоваться меньше места. Или можно попробовать запускать процесс очистки в OldGen раньше (это можно сделать с помощью параметра CMSInitiatingOccupancyFraction), чтобы к началу сборки в YoungGen в OldGen было достаточно места.

Попробуем один из этих способов — уменьшим размер YoungGen (по умолчанию он составлял 15Mb), используем параметр NewRatio=100, при этом YoungGen будет занимать около 5MB:

$ java -Xmx512M -XX:+ UseConcMarkSweepGC -XX:-UseParNewGC -XX:NewRatio=100 TestGCPause

В этом случае получаем отличный результат:

Max pause 304ms

Запустив приложение с флагом PrintGCDetails, можно убедиться, что CMS при таких настройках действительно работает без сбоев. Таким образом, CMS на самом деле помог избавиться от двухсекундных пауз, которые возникали при использовании последовательного сборщика мусора!

Это был простой пример, но, надеюсь, он показал, что для использования CMS могут потребоваться некоторые знания о его работе. На работу CMS влияет довольно много параметров, о которых можно, например, прочитать в документе Java SE 6 HotSpot[tm] Virtual Machine Garbage Collection Tuning или блоге Йона Мацамицу (Jon Masamitsu), одного из разработчиков виртуальной машины.

Ссылки

• Java HotSpot Garbage Collection
• Memory Management in the Java HotSpot™ Virtual Machine
• Understanding CMS GC Logs