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

Настраиваем последовательный сборщик мусора

Всем хочется, чтобы работа сборщика мусора была абсолютно незаметна – приложение не должно полностью приостанавливаться на время сборки мусора, сборщик мусора не должен отнимать процессорное время у приложения, и свободной памяти у программы должно быть всегда столько, сколько ей требуется. Однако на практике пользователи часто жалуются, что сборщик мусора работает слишком медленно, или что приложение завершает работу из-за OutOfMemoryError. Сегодня мы на примере последовательного сборщика попытаемся понять, что можно сделать, если сборка мусора начинает негативно влиять на работу вашего приложения.

Для экспериментов будем использовать простейшую программу, которая в течении одной минуты создаёт множество объектов, тем самым провоцируя работу сборщика мусора (TestGC.java). Чтобы можно было ощутить влияние сборщика мусора на работу программы, помимо потока, генерирующего мусор, также запускается второй поток, периодически выполняющий набор арифметических действий и замеряющий время, затраченное на эти вычисления. В конце работы программы выводится среднее и максимальное время, занятое вычислениями. Конечно, эта программа вряд ли отражает поведение типичной Java-программы и её ни в коем случае нельзя использовать для оценки производительности сборщика мусора, но она отлично подходит для наших целей.

Программа запускалась с использованием JDK6 на машине под управлением ОС SuSE Linux 9.2, имеющей 1 GB оперативной памяти и процессор Pentium 4. Эта конфигурация попадает под определение машины 'клиентского типа', и поэтому по умолчанию виртуальной машина использует последовательный сборщик мусора (SerialGC).

Для начала посмотрим, как ведёт себя программа, если в процессе её работы мусор не генерируется, для этого запустим её с параметром -generateGarbageOff. В этом случае главный поток хоть и не генерирует мусор, но при этом постоянно проверяет условие завершение работы программы, занимая тем самым процессорное время. Ещё одна небольшая деталь: чтобы JIT-компилятор не влиял на результаты измерения времени, будем запускать виртуальную машину в режиме интерпретации (при котором JIT-компиляция не выполняется). Для этого используем флаг -Xint:

java -Xint TestGC -generateGarbageOff

После работы в течении минуты программа выдала следующий результат:

Максимальное время: 452
Среднее время: 447.41177

Теперь посмотрим, окажет ли какое-нибудь влияние на результаты работы генерация мусора (уберём параметр -generateGarbageOff):

java -Xint TestGC

Вот что получилось в этот раз:

Максимальное время: 1357
Среднее время: 470.91742

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

Далее проверим, что причиной замедления приложения действительно является работа сборщика мусора. Проще всего для этого использовать флаг -verbose:gc или -XX:+PrintGC. При использовании одного из этих флагов после каждой сборки мусора виртуальная машина выводит сообщения в следующем формате:

• [GC <allocatedMemoryBefore>-><allocatedMemoryAfter>(<heap size>), <time> secs],
  если сборка мусора проводилась только в Young generation
• [Full GC <allocatedMemoryBefore>-><allocatedMemoryAfter>(<heap size>), <time> secs],
  если сборка мусора проводилась во всей куче

где

• <allocatedMemoryBefore>—занятая память перед началом работы сборщика мусора
• <allocatedMemoryAfter>—занятая память после завершения работы сборщика мусора
• <heap size>—текущий размер кучи
• <time>—время, затраченное на сборку мусора

Запустим программу с использованием флага -XX:+PrintGC:

java -Xint -XX:+PrintGC TestGC

Использование этого флага показывает, что во время работы программы сборка мусора выполнялась ~400 раз. Вот фрагмент полученного вывода:

...
Начинаем вычисления
[GC 48140K->48139K(51516K), 0.0343350 secs]
[Full GC 48139K->48139K(51516K), 0.2572570 secs]
[GC 51964K->51963K(65088K), 0.1138630 secs]
[GC 56059K->54876K(65088K), 0.0295040 secs]
Вычисления окончены, время: 797
...

Получается, что в тот момент, когда поток производил вычисления, несколько раз производилась сборка мусора, а так как последовательный сборщик мусора использует модель работы stop-the-world (то есть приостанавливает все потоки приложения на время своей работы), он действительно влияет на время выполнения программы.

Попытаемся получить более подробную информацию о работе сборщика мусора. Это можно сделать, например, с помощью флага -XX:+PrintGCDetails, который формирует более детальный отчёт, чем с -XX:+PrintGC. Формат вывода зависит от используемого сборщика мусора. Для последовательного сборщика сообщения имеют следующий вид:

[GC [DefNew: <newAllocatedBefore>-><newAllocatedAfter>(<new size>), <newTime> secs]
    <totalAllocatedBefore>-><totalAllocatedAfter>(<heap size>), <totalTime> secs]

где

• <newAllocatedBefore>—занятая память в Young generation перед началом работы сборщика мусора
• <newAllocatedAfter>—занятая память в Young generation после завершения работы сборщика мусора
• <new size>—текущий размер Young generation
• <newTime>—время, затраченное на сборку мусора в Young generation
• <totalAllocatedBefore>—общий размер занятой памяти перед началом работы сборщика мусора
• <totalAllocatedAfter>—общий размер занятой памяти после завершения работы сборщика мусора
• <heap size>—текущий размер кучи
  
• <totalTime>—полное время, затраченное на сборку мусора (может также включать время на сборку мусора в Old generation, если она выполнялась)

После сборки мусора в Old generation, строка вывода будет содержать:

[Tenured: <allocatedBefore>-><allocatedAfter>(<old size>), <time1> secs]

Вот сокращённая версия вывода, полученного с использованием флага -XX:+PrintGCDetails:

[GC [DefNew: 896K->64K(960K), 0.0081620 secs] 896K->755K(5056K), 0.0082540 secs]
...
[GC [DefNew: 960K->64K(960K), 0.0083930 secs] 6910K->6909K(8000K), 0.0084680 secs]
[GC [DefNew: 960K->63K(960K), 0.0078980 secs]
    [Tenured: 7740K->7804K(7836K), 0.0456450 secs] 7805K->7804K(8796K), 0.0537530 secs]
[GC [DefNew: 1024K->64K(1088K), 0.0089900 secs] 8828K->8826K(14096K), 0.0090620 secs]
...
[GC [DefNew: 1792K->191K(1792K), 0.0151140 secs] 21899K->21898K(24968K), 0.0151840 secs]
[GC [DefNew: 1791K->192K(1792K), 0.0155790 secs]
    [Tenured: 23306K->22941K(23432K), 0.1632510 secs] 23498K->22941K(25224K), 0.1790300 secs]
[GC [DefNew: 2560K->319K(2880K), 0.0210130 secs] 25501K->25500K(41116K), 0.0211100 secs]
...
[GC [DefNew: 4032K->448K(4032K), 0.0080090 secs] 53827K->50794K(57088K), 0.0080850 secs]
[GC [DefNew: 4032K->448K(4032K), 0.0392930 secs]
    [Tenured: 53927K->5845K(53952K), 0.0666280 secs] 54378K->5845K(57984K), 0.1081950 secs]
[GC [DefNew: 2752K->319K(3072K), 0.0226030 secs] 8597K->8596K(43240K), 0.0226710 secs]
...
[GC [DefNew: 3071K->320K(3072K), 0.0260060 secs] 38856K->38855K(43240K), 0.0260780 secs]
[GC [DefNew: 3072K->319K(3072K), 0.0284590 secs]
    [Tenured: 41286K->41320K(41320K), 0.2301340 secs] 41607K->41606K(44392K), 0.2588120 secs]
[GC [DefNew: 4096K->447K(4544K), 0.1129120 secs] 45416K->45412K(65088K), 0.1129780 secs]
...
[GC [DefNew: 4544K->447K(4544K), 0.0433850 secs] 60339K->60338K(65088K), 0.0434540 secs]
[GC [DefNew: 4543K->4543K(4544K), 0.0000650 secs]
    [Tenured: 59890K->15479K(60544K), 0.1349180 secs] 64434K->15479K(65088K), 0.1351480 secs]
[GC [DefNew: 4096K->447K(4544K), 0.0333840 secs] 19575K->19573K(64196K), 0.0334540 secs]

Можно обратить внимание на то, что размер Young Generation и Old Generation регулярно изменяется и это изменение происходит после сборок мусора в Old Generation. Например:

[GC [DefNew: 960K->64K(960K), 0.0083930 secs] 6910K->6909K(8000K), 0.0084680 secs]
[GC [DefNew: 960K->63K(960K), 0.0078980 secs]
    [Tenured: 7740K->7804K(7836K), 0.0456450 secs] 7805K->7804K(8796K), 0.0537530 secs]
[GC [DefNew: 1024K->64K(1088K), 0.0089900 secs] 8828K->8826K(14096K), 0.0090620 secs]

Вторая строка содержит информацию о сборке мусора в Old Generation([Tenured: 7740K->7804K(7836K), 0.0456450 secs]), при этом размер Young Generation составлял 960K. Из следующей строки видно, что размер Young Generation увеличился до 1088K.

Также заметим, что размер поколений может и уменьшаться:

[GC [DefNew: 4096K->448K(4096K), 0.0136040 secs] 54394K->51863K(58528K), 0.0136640 secs]
[GC [DefNew: 4096K->448K(4096K), 0.0368500 secs]
    [Tenured: 55061K->6477K(55072K), 0.0722570 secs] 55511K->6477K(59168K), 0.1143090 secs]
[GC [DefNew: 1600K->128K(1728K), 0.0143750 secs] 8077K->8076K(23324K), 0.0144410 secs]

В связи с чем происходят эти изменения в размерах Old Generation и Young Generation? Дело в том, что в процессе работы сборщик мусора пытается оптимизировать размеры поколений—чтобы они не были не слишком большие, но и не чересчур маленькие. Если размер поколения слишком мал, оно быстро заполняется, и это провоцирует частые сборки мусора. В тоже время, излишне большой размер кучи, превышающий требования приложения, также нежелателен. Поведение сборщика мусора определяется двумя параметрами—MinHeapFreeRatio и MaxHeapFreeRatio. Если после сборки мусора размер свободной памяти меньше, чем значение MinHeapFreeRatio, то размер поколения увеличивается, а если свободной памяти больше, чем MaxHeapFreeRatio, то уменьшается. По умолчанию MinHeapFreeRatio=40, MaxHeapFreeRatio=70.

Рассмотрим, как меняется размер Old Generation, добавив к флагу -XX:+PrintGCDetails ещё один флаг: -XX:+PrintHeapAtGC. С этим флагом выводится ещё больше информации о каждой сборке мусора, причём отдельно выводится информация о состоянии памяти до и после сборки мусора:

{Heap before GC invocations=20 (full 0):
 def new generation   total 1792K, used 1792K [0x42340000, 0x42530000, 0x42820000)
  eden space 1600K, 100% used [0x42340000, 0x424d0000, 0x424d0000)
  from space 192K, 100% used [0x42500000, 0x42530000, 0x42530000)
  to   space 192K,   0% used [0x424d0000, 0x424d0000, 0x42500000)
 tenured generation   total 23176K, used 21706K [0x42820000, 0x43ec2000, 0x46340000)
   the space 23176K,  93% used [0x42820000, 0x43d52be0, 0x43d52c00, 0x43ec2000)
 compacting perm gen  total 12288K, used 1660K [0x46340000, 0x46f40000, 0x4a340000)
   the space 12288K,  13% used [0x46340000, 0x464df390, 0x464df400, 0x46f40000)
No shared spaces configured.
[GC [DefNew: 1792K->192K(1792K), 0.0205550 secs]
    [Tenured: 23306K->22941K(23432K), 0.1712380 secs] 23498K->22941K(25224K), 0.1920160 secs]
Heap after GC invocations=21 (full 0):
 def new generation   total 2880K, used 0K [0x42340000, 0x42660000, 0x42820000)
  eden space 2560K,   0% used [0x42340000, 0x42340000, 0x425c0000)
  from space 320K,   0% used [0x425c0000, 0x425c0000, 0x42610000)
  to   space 320K,   0% used [0x42610000, 0x42610000, 0x42660000)
 tenured generation   total 38240K, used 22941K [0x42820000, 0x44d78000, 0x46340000)
   the space 38240K,  59% used [0x42820000, 0x43e87688, 0x43e87800, 0x44d78000)
 compacting perm gen  total 12288K, used 1658K [0x46340000, 0x46f40000, 0x4a340000)
   the space 12288K,  13% used [0x46340000, 0x464deb88, 0x464dec00, 0x46f40000)
No shared spaces configured.
}

Думаю, что формат вывода понятен.

Строка

[GC [DefNew: 1792K->192K(1792K), 0.0205550 secs]
    [Tenured: 23306K->22941K(23432K), 0.1712380 secs] 23498K->22941K(25224K), 0.1920160 secs]

говорит о том, что было произведено 2 сборки мусора в Young Generation (DefNew: 1792K->192K(1792K)) и Old Generation (Tenured: 23306K->22941K(23432K)).

До сборки мусора размер Old Generation составлял 23 176 K:

{Heap before GC
...
tenured generation   total 23176K, used 21706K [0x42820000, 0x43ec2000, 0x46340000

После сборки мусора в Young Generation часть объектов, переживших эту сборку, была перемещена в Old Generation, это перемещение увеличило размер занятой памяти в Old Generation до 23306K и спровоцировало сборку мусора в Old Generation. В результате этой сборки мусора размер занятой памяти в Old Generation уменьшился с 23306K до 22941K (Tenured: 23306K->22941K), и процент занятой памяти в Old Generation стал равен 98%, что не соответствует параметру MinHeapFreeRatio, поэтому размер Old Generation был увеличен так, чтобы процент занятого места в нём был равен (100 - MinHeapFreeRatio), то есть 60%:

Heap after GC
...
 tenured generation   total 38240K, used 22941K [0x42820000, 0x44d78000, 0x46340000)
   the space 38240K,  59% used [0x42820000, 0x43e87688, 0x43e87800, 0x44d78000)

Можем ли мы как-нибудь повлиять на работу сборщика мусора, например, уменьшить частоту его запуска?

Посмотрим, что происходит c памятью приложения с текущими настройками по умолчанию. К использовавшимся ранее флагам добавим ещё один: -XX:+PrintGCTimeStamps, использование которого добавляет к сообщению о сборке мусора время её начала (время измеряется относительно момента запуска приложения), так что можно проследить, как часто в нашем приложении происходит сборка мусора:

...
1.012: [GC 1.012: [DefNew: 1088K->64K(1088K), 0.0077080 secs]1.020: 
    [Tenured: 13849K->13913K(13968K), 0.1003270 secs] 13913K->13913K(15056K), 0.1082060 secs]
1.171: [GC 1.171: [DefNew: 1600K->192K(1792K), 0.0191240 secs] 15513K->15513K(24984K), 0.0191970 secs]
1.246: [GC 1.246: [DefNew: 1792K->192K(1792K), 0.0248720 secs] 17113K->17113K(24984K), 0.0250570 secs]
1.327: [GC 1.327: [DefNew: 1792K->192K(1792K), 0.0250080 secs] 18713K->18713K(24984K), 0.0251200 secs]
1.428: [GC 1.428: [DefNew: 1792K->192K(1792K), 0.0164400 secs] 20313K->20306K(24984K), 0.0165190 secs]
1.483: [GC 1.483: [DefNew: 1791K->192K(1792K), 0.0199000 secs] 21906K->21901K(24984K), 0.0200210 secs]
1.561: [GC 1.561: [DefNew: 1792K->192K(1792K), 0.0263100 secs]1.587: 
    [Tenured: 23309K->22600K(23320K), 0.1984640 secs] 23501K->22600K(25112K), 0.2250640 secs]
...

Судя по полученному выводу, в течении одной секунды область Young Generation заполнялась 5 раз, после сборок мусора часть объектов из Young Generation перемещалась в Old Generation, в результате чего область Old Generation также была переполнена и в ней была запущена сборка мусора.

Каким образом можно оптимизировать работу сборщика мусора? Для приложений, интенсивно создающих много объектов с небольшим временем жизни, можно увеличить размер Young Generation. Оптимально подобранный размер Young Generation позволяет минимизировать количество запусков сборщика мусора, и если в процессе работы приложения не создаётся много долго живущих объектов, переживающих сборки мусора в Young Generation, то возможно вообще избежать длительных очисток Old Generation.

Как мы уже видели, размер Young Generation увеличивается и автоматически, но только до определённого максимального значения, и виртуальная машина предоставляет возможность задать это максимальное значение. Максимальный размер Young Generation можно задать, например, с помощью параметра NewRatio. NewRatio задаёт отношение между размером Old Generation и Young Generation, например, в нашем случае значение NewRatio по умолчанию равно 12, то есть Young gen занимает около 1/13 всей памяти.

Вот как изменяется работа сборщика мусора в нашем приложении с увеличенным размером Young Generation (запускаем виртуальную машину с флагом -XX:NewRatio=5):

...
6.283: [GC 6.283: [DefNew: 9791K->9791K(9792K), 0.0000590 secs]6.283: 
    [Tenured: 50892K->9121K(54656K), 0.0939500 secs] 60684K->9121K(64448K), 0.0942140 secs]
6.644: [GC 6.644: [DefNew: 8448K->1024K(9472K), 0.0726740 secs] 17569K->17565K(61704K), 0.0727500 secs]
6.991: [GC 6.991: [DefNew: 9472K->1024K(9472K), 0.0785940 secs] 26013K->26010K(61704K), 0.0786720 secs]
7.449: [GC 7.449: [DefNew: 9472K->1024K(9472K), 0.1121980 secs] 34458K->34455K(61704K), 0.1122700 secs]
7.841: [GC 7.841: [DefNew: 9472K->1023K(9472K), 0.0764330 secs] 42903K->42900K(61704K), 0.0765050 secs]
8.195: [GC 8.195: [DefNew: 9471K->1024K(9472K), 0.0767590 secs] 51348K->51300K(61704K), 0.0768380 secs]
8.563: [GC 8.563: [DefNew: 9472K->9472K(9472K), 0.0000560 secs]8.563: 
    [Tenured: 50276K->7575K(52232K), 0.0885610 secs] 59748K->7575K(61704K), 0.0905710 secs]
...

Теперь сборка мусора происходит 2–3 раза в секунду (общее число запуска сборщика мусора сократилось с 400 до 170), и время между сборками мусора в Old Generation теперь составляет около двух секунд.

Увеличивая размер Young Generation, не перестарайтесь! Вот как станет вести себя сборщик мусора, если задать NewRatio=1:

...
24.441: [GC 24.441: [DefNew: 26240K->26240K(29504K), 0.0000550 secs]24.441: 
    [Tenured: 7442K->32768K(32768K), 0.2573070 secs] 33682K->33679K(62272K), 0.2574700 secs]
25.408: [Full GC 25.408: 
    [Tenured: 32768K->7442K(32768K), 0.0841450 secs] 59008K->7442K(62272K), [Perm : 1658K->1658K(12288K)], 0.0842330 secs]
26.193: [GC 26.193: [DefNew: 26240K->3264K(29504K), 0.2386900 secs] 33682K->33679K(62272K), 0.2387550 secs]
27.127: [Full GC 27.127: 
    [Tenured: 30415K->8353K(32768K), 0.0907830 secs] 59919K->8353K(62272K), [Perm : 1658K->1658K(12288K)], 0.0910560 secs]
27.882: [GC 27.882: [DefNew: 25920K->25920K(29120K), 0.0000560 secs]27.882:
    [Tenured: 8353K->32276K(32276K), 0.2565320 secs] 34273K->34270K(61396K), 0.2567300 secs]
28.812: [Full GC 28.812: 
    [Tenured: 32276K->6950K(32768K), 0.0773670 secs] 58516K->6950K(62272K), [Perm : 1658K->1658K(12288K)], 0.0774550 secs]
29.583: [GC 29.583: [DefNew: 26240K->26240K(29504K), 0.0000620 secs]29.583:
    [Tenured: 6950K->32767K(32768K), 0.2488050 secs] 33190K->33187K(62272K), 0.2489770 secs]
30.513: [Full GC 30.513:
    [Tenured: 32767K->7442K(32768K), 0.0838540 secs] 59007K->7442K(62272K), [Perm : 1658K->1658K(12288K)], 0.0840120 secs]
31.324: [GC 31.324: [DefNew: 26240K->26240K(29504K), 0.0000610 secs]31.324: 
    [Tenured: 7442K->32768K(32768K), 0.2523010 secs] 33682K->33678K(62272K), 0.2524720 secs]
32.259: [Full GC 32.259:
    [Tenured: 32768K->7442K(32768K), 0.0888470 secs] 59008K->7442K(62272K), [Perm : 1658K->1658K(12288K)], 0.0889310 secs]
33.050: [GC 33.050: [DefNew: 26240K->26240K(29504K), 0.0000610 secs]33.050: 
    [Tenured: 7442K->32768K(32768K), 0.2508870 secs] 33682K->33679K(62272K), 0.2510630 secs]
34.002: [Full GC 34.002:
    [Tenured: 32768K->7442K(32768K), 0.0849230 secs] 59008K->7442K(62272K), [Perm : 1658K->1658K(12288K)], 0.0850110 secs]
...

Происходит следующее: после заполнения Young Generation сборщик мусора проверяет, что в Old Generation достаточно места для возможного перемещения объектов из Young Generation в Old Generation. При очень больших размерах Young Generation эта проверка заканчивается неудачно и сборка мусора в Young Generation не выполняется (26240K->26240K(29504K), 0.0000550 secs), а вместо этого Young Generation очищается вместе с Old Generation, и в следующий раз, когда Young Generation переполняется, сборка мусора в Young Generation не производится, а сразу выполняется полная сборка мусора (Full GC).

При таком поведении теряется выгода разделения памяти на поколения (так как в этом случае отдельные сборки мусора в Young Generation не выполняются) и приложение постоянно приостанавливается на время длительных сборок мусора выполняемых во всей Heap памяти (даже в нашем простом примере с небольшим объёмом Heap памяти сборка мусора в Old Generation занимает на порядок больше времени, чем в Young Generation).

Надеюсь, приведённая информация будет полезна тем, кто столкнулся с проблемами, связанными со сборкой мусора. Конечно, помимо описанных в этом посте, есть ещё немало возможностей для мониторинга и настройки работы сборщика мусора (об этом можно узнать из документации, доступной на java.sun.com, а также из исходников Hotspot), и о некоторых из этих возможностей мы обязательно расскажем в следующих постах.

Ссылки:

• Java HotSpot Garbage Collection
• Memory Management in the Java HotSpot™ Virtual Machine
• Frequently Asked Questions about Garbage Collection in the HotspotTM JavaTM Virtual Machine
• Diagnosing a Garbage Collection problem

Семён Бойков