Автор оригинала: Jonathan Cook.
1. Обзор
В этом уроке мы рассмотрим, как включить подробную сборку мусора в Java-приложении . Мы начнем с представления того, что такое многословная сборка мусора и почему она может быть полезна.
Далее мы рассмотрим несколько различных примеров и узнаем о различных доступных параметрах конфигурации. Кроме того, мы также сосредоточимся на том, как интерпретировать выходные данные наших подробных журналов.
Чтобы узнать больше о сборке мусора (GC) и различных доступных реализациях, ознакомьтесь с нашей статьей о сборщиках мусора Java .
2. Краткое введение в подробный сбор мусора
Включение подробного ведения журнала сборки мусора часто требуется при настройке и отладке многих проблем , особенно проблем с памятью. На самом деле, некоторые утверждают, что для того, чтобы строго контролировать работоспособность вашего приложения, мы всегда должны следить за производительностью сборки мусора JVM.
Как мы увидим, журнал GC является очень важным инструментом для выявления потенциальных улучшений в конфигурации кучи и GC нашего приложения. Для каждого события GC журнал GC предоставляет точные данные о его результатах и продолжительности.
Со временем анализ этой информации может помочь нам лучше понять поведение нашего приложения и настроить производительность нашего приложения. Кроме того, он может помочь оптимизировать частоту GC и время сбора, указав наилучшие размеры кучи, другие параметры JVM и альтернативные алгоритмы GC.
2.1. Простая Программа На Java
Мы будем использовать простую программу Java, чтобы продемонстрировать, как включить и интерпретировать наши журналы GC:
public class Application {
private static Map stringContainer = new HashMap<>();
public static void main(String[] args) {
System.out.println("Start of program!");
String stringWithPrefix = "stringWithPrefix";
// Load Java Heap with 3 M java.lang.String instances
for (int i = 0; i < 3000000; i++) {
String newString = stringWithPrefix + i;
stringContainer.put(newString, newString);
}
System.out.println("MAP size: " + stringContainer.size());
// Explicit GC!
System.gc();
// Remove 2 M out of 3 M
for (int i = 0; i < 2000000; i++) {
String newString = stringWithPrefix + i;
stringContainer.remove(newString);
}
System.out.println("MAP size: " + stringContainer.size());
System.out.println("End of program!");
}
} Как мы можем видеть в приведенном выше примере, эта простая программа загружает 3 миллиона экземпляров String в объект Map . Затем мы делаем явный вызов сборщика мусора с помощью System.gc() .
Наконец, мы удаляем 2 миллиона экземпляров String из Map . Мы также явно используем System.out.println , чтобы упростить интерпретацию выходных данных.
В следующем разделе мы рассмотрим, как активировать ведение журнала GC.
3. Активация “простого” ведения журнала ГК
Давайте начнем с запуска нашей программы и включения подробного GC с помощью наших аргументов запуска JVM:
-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc
Важным аргументом здесь является -verbose:gc , который активирует протоколирование информации о сборке мусора в простейшей форме . По умолчанию журнал GC записывается в stdout и должен выводить строку для каждого GC молодого поколения и каждого полного GC.
Для целей нашего примера мы указали последовательный сборщик мусора, простейшую реализацию GC, с помощью аргумента -XX:+UseSerialGC .
Мы также установили минимальный и максимальный размер кучи в 1024 Мб, но, конечно, есть и другие параметры JVM, которые мы можем настроить.
3.1. Базовое понимание подробного вывода
Теперь давайте посмотрим на результат нашей простой программы:
Start of program! [GC (Allocation Failure) 279616K->146232K(1013632K), 0.3318607 secs] [GC (Allocation Failure) 425848K->295442K(1013632K), 0.4266943 secs] MAP size: 3000000 [Full GC (System.gc()) 434341K->368279K(1013632K), 0.5420611 secs] [GC (Allocation Failure) 647895K->368280K(1013632K), 0.0075449 secs] MAP size: 1000000 End of program!
В приведенном выше выводе мы уже видим много полезной информации о том, что происходит внутри JVM.
Поначалу этот вывод может показаться довольно сложным, но давайте теперь рассмотрим его шаг за шагом.
Прежде всего, мы видим, что состоялось четыре сбора, один полный GC и три очистки молодых поколений.
3.2. Подробный Вывод более подробно
Давайте разложим выходные строки более подробно, чтобы точно понять, что происходит:
- GC или Полный GC – Тип сбора мусора, либо GC , либо Полный GC , чтобы отличить незначительный или полный сбор мусора
- (Сбой выделения) или (System.gc()) – Причина сбоя выделения коллекции – Указывает на то, что в Eden больше не осталось места для размещения наших объектов
- 279616K->146232K – Занятая память кучи до и после GC соответственно (разделена стрелкой)
- (1013632K) – Текущая емкость кучи
- 0.3318607 сек – Продолжительность события GC в секундах
Таким образом, если мы возьмем первую строку, 279616K->146232K(1013632K) означает, что GC уменьшил занимаемую память кучи с 279616K до 146232K . Емкость кучи на момент GC составляла 1013632K , и GC занимал 0.3318607 секунды.
Однако, хотя простой формат ведения журнала GC может быть полезен, он предоставляет ограниченные сведения. Например, мы не можем сказать, переместил ли GC какие-либо объекты из молодого поколения в старое или каков был общий размер молодого поколения до и после каждой коллекции .
По этой причине подробное ведение журнала GC более полезно, чем простое.
4. Активация “подробного” ведения журнала ГК
Чтобы активировать подробное ведение журнала GC, мы используем аргумент -XX:+PrintGCDetails . Это даст нам более подробную информацию о каждом GC, например:
- Численность молодого и старого поколения до и после каждого GC
- Время, необходимое для того, чтобы GC произошел в молодом и старом поколении
- Размер объектов, продвигаемых на каждом GC
- Сводная информация о размере общей кучи
В следующем примере мы увидим, как получить еще более подробную информацию в наших журналах, комбинируя -verbose:gc с этим дополнительным аргументом.
Обратите внимание, что флаг -XX:+PrintGCDetails устарел в Java 9 в пользу нового унифицированного механизма ведения журнала (подробнее об этом позже). В любом случае, новым эквивалентом -XX:+PrintGCDetails является опция -Xlog:gc* .
5. Интерпретация “подробного” подробного вывода
Давайте снова запустим нашу примерную программу:
-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc -XX:+PrintGCDetails
На этот раз результат будет более подробным:
Start of program! [GC (Allocation Failure) [DefNew: 279616K->34944K(314560K), 0.3626923 secs] 279616K->146232K(1013632K), 0.3627492 secs] [Times: user=0.33 sys=0.03, real=0.36 secs] [GC (Allocation Failure) [DefNew: 314560K->34943K(314560K), 0.4589079 secs] 425848K->295442K(1013632K), 0.4589526 secs] [Times: user=0.41 sys=0.05, real=0.46 secs] MAP size: 3000000 [Full GC (System.gc()) [Tenured: 260498K->368281K(699072K), 0.5580183 secs] 434341K->368281K(1013632K), [Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs] [Times: user=0.50 sys=0.06, real=0.56 secs] [GC (Allocation Failure) [DefNew: 279616K->0K(314560K), 0.0076722 secs] 647897K->368281K(1013632K), 0.0077169 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] MAP size: 1000000 End of program! Heap def new generation total 314560K, used 100261K [0x00000000c0000000, 0x00000000d5550000, 0x00000000d5550000) eden space 279616K, 35% used [0x00000000c0000000, 0x00000000c61e9370, 0x00000000d1110000) from space 34944K, 0% used [0x00000000d3330000, 0x00000000d3330188, 0x00000000d5550000) to space 34944K, 0% used [0x00000000d1110000, 0x00000000d1110000, 0x00000000d3330000) tenured generation total 699072K, used 368281K [0x00000000d5550000, 0x0000000100000000, 0x0000000100000000) the space 699072K, 52% used [0x00000000d5550000, 0x00000000ebcf65e0, 0x00000000ebcf6600, 0x0000000100000000) Metaspace used 2637K, capacity 4486K, committed 4864K, reserved 1056768K class space used 283K, capacity 386K, committed 512K, reserved 1048576K
Мы должны быть в состоянии распознать все элементы из простого журнала GC. Но есть несколько новых пунктов.
Теперь давайте рассмотрим новые элементы в выводе, которые выделены синим цветом в следующем разделе:
5.1. Интерпретация несовершеннолетнего GC в Молодом поколении
Мы начнем с анализа новых частей в незначительном GC:
- [[GC (Сбой выделения) [Определить: 279616K->34944K(314560K), 0,3626923 секунды] |/279616K->146232K(1013632K), 0,3627492 секунды] [Время:.33.03,.36 секунды]
Как и прежде, мы разобьем линии на части:
- DefNew – Имя используемого сборщика мусора. Это не столь очевидное название расшифровывается как однопоточный сборщик мусора mark-copy stop-the-world и используется для очистки молодого поколения
- 279616K->34944K – Использование молодого поколения до и после сбора
- (314560K) – Общий размер молодого поколения
- 0.3626923 секунды – Продолжительность в секундах
- [Время:.33.03,.36 сек ] – Продолжительность события GC, измеренная в разных категориях
Теперь давайте объясним различные категории:
- пользователь – Общее время процессора, затраченное сборщиком мусора
- sys – Время, затраченное на вызовы ОС или ожидание системных событий
- реальный – Это все прошедшее время, включая временные срезы, используемые другими процессами
Поскольку мы выполняем наш пример с использованием последовательного сборщика мусора, который всегда использует только один поток, реальное время равно сумме времени пользователя и системы.
5.2. Интерпретация полного GC
В этом предпоследнем примере мы видим, что для основной коллекции (Полная GC), которая была вызвана нашим системным вызовом, используемый коллектор был Арендован .
Последняя часть дополнительной информации, которую мы видим, – это разбивка по той же схеме для Метапространства :
[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]
Метапространство это новый объем памяти введено в Java 8 и является областью собственной памяти.
5.3. Анализ разбивки кучи Java
Заключительная часть вывода включает в себя разбивку кучи, включая сводку объема памяти для каждой части памяти .
Мы видим, что площадь Eden space составляла 35% , а площадь Tenured-52%. Также включена сводка для пространства метаданных и пространства классов.
Из приведенных выше примеров теперь мы можем точно понять, что происходило с потреблением памяти внутри JVM во время событий GC.
6. Добавление информации о дате и времени
Ни один хороший журнал не является полным без информации о дате и времени.
Эта дополнительная информация может быть очень полезна, когда нам нужно сопоставить данные журнала GC с данными из других источников, или она может просто помочь облегчить поиск.
Мы можем добавить следующие два аргумента при запуске нашего приложения, чтобы информация о дате и времени отображалась в наших журналах:
-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps
Каждая строка теперь начинается с абсолютной даты и времени, когда она была написана, за которой следует метка времени, отражающая реальное время, прошедшее в секундах с момента запуска JVM:
2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...
Обратите внимание, что эти флаги настройки были удалены в Java 9. Новая альтернатива:
-Xlog:gc*::time
7. Запись в файл
Как мы уже видели, по умолчанию журнал GC записывается в stdout . Более практичным решением является указание выходного файла.
Мы можем сделать это, используя аргумент -Xloggc:<файл> где файл это абсолютный путь к нашему выходному файлу:
-Xloggc:/path/to/file/gc.log
Как и другие флаги настройки, Java 9 устарел флаг-Xloggc в пользу нового унифицированного ведения журнала. Чтобы быть более конкретным, теперь альтернативой для входа в файл является:
-Xlog:gc:/path/to/file/gc.log
8. Java 9: Унифицированное ведение журнала JVM
Начиная с Java 9, большинство флагов настройки, связанных с GC, устарели в пользу опции унифицированного ведения журнала -Xlog:gc . Однако опция – verbose:gc по-прежнему работает в Java 9 и более новой версии.
Например, начиная с Java 9, эквивалентом флага -verbose:gc в новой единой системе ведения журнала является:
-Xlog:gc
Это позволит записать все журналы GC уровня информации в стандартный вывод. Также можно использовать синтаксис -Xlog:gc= для изменения уровня журнала. Например, чтобы просмотреть все журналы уровня отладки:
-Xlog:gc=debug
Как мы видели ранее, мы можем изменить назначение вывода с помощью синтаксиса -Xlog:gc=: . По умолчанию output является stdout , но мы можем изменить его на stderr или даже файл:
-Xlog:gc=debug:file=gc.txt
Кроме того, можно добавить еще несколько полей в выходные данные с помощью декораторов. Например:
-Xlog:gc=debug::pid,time,uptime
Здесь мы печатаем идентификатор процесса, время безотказной работы и текущую метку времени в каждой инструкции журнала.
Дополнительные примеры унифицированного ведения журнала JVM см. в стандарте JEP 158 .
9. Инструмент для анализа журналов ГК
Анализ журналов ГК с помощью текстового редактора может занять много времени и быть довольно утомительным. В зависимости от версии JVM и используемого алгоритма GC формат журнала GC может отличаться.
Существует очень хороший бесплатный инструмент графического анализа, который анализирует журналы сбора мусора, предоставляет множество показателей о потенциальных проблемах сбора мусора и даже предоставляет потенциальные решения этих проблем.
Обязательно ознакомьтесь с Universal GC Log Analyzer !
10. Заключение
Подводя итог, в этом уроке мы подробно рассмотрели многословную сборку мусора в Java.
Во-первых, мы начали с представления того, что такое многословная сборка мусора и почему мы можем захотеть ее использовать. Затем мы рассмотрели несколько примеров с использованием простого Java-приложения. Мы начали с включения ведения журнала GC в его простейшей форме, прежде чем изучить несколько более подробных примеров и способы интерпретации выходных данных.
Наконец, мы рассмотрели несколько дополнительных опций для регистрации информации о времени и дате, а также для записи информации в файл журнала.
Примеры кода можно найти на GitHub .