Перейти к основному содержимому

Подробная сборка мусора в Java

· 10 мин. чтения

1. Обзор​

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

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

Чтобы узнать больше о сборке мусора (GC) и различных доступных реализациях, ознакомьтесь с нашей статьей о сборщиках мусора Java .

2. Краткое введение в подробную сборку мусора​

Включение подробного ведения журнала сборки мусора часто требуется при настройке и отладке многих проблем , особенно проблем с памятью. На самом деле, некоторые утверждают, что для того, чтобы строго следить за работоспособностью нашего приложения, мы всегда должны следить за производительностью сборки мусора JVM.

Как мы увидим, журнал GC — очень важный инструмент для выявления потенциальных улучшений кучи и конфигурации GC нашего приложения. Для каждого события GC журнал GC предоставляет точные данные о его результатах и продолжительности.

Со временем анализ этой информации может помочь нам лучше понять поведение нашего приложения и настроить его производительность. Кроме того, он может помочь оптимизировать частоту и время сбора мусора, указав оптимальные размеры кучи, другие параметры JVM и альтернативные алгоритмы сбора мусора.

2.1. Простая Java-программа​

Мы будем использовать простую программу Java, чтобы продемонстрировать, как включить и интерпретировать наши журналы GC:

public class Application {

    private static Map<String, String> 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 из карты . Мы также явно используем System.out.println , чтобы упростить интерпретацию вывода.

В следующем разделе мы увидим, как активировать ведение журнала сборщика мусора.

3. Активация «простого» ведения журнала сборщика мусора​

Давайте начнем с запуска нашей программы и включения подробного GC через наши начальные аргументы JVM:

-XX:+UseSerialGC -Xms1024m -Xmx1024m -verbose:gc

Важным аргументом здесь является -verbose: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.

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

Во-первых, мы видим, что состоялось четыре сбора, один Full GC и три очистки Young Generation.

3.2. Подробный вывод более подробно​

Давайте разберем выходные строки более подробно, чтобы понять, что именно происходит:

  1. GC или Full GC — тип сборки мусора, либо GC , либо полный GC , чтобы различать второстепенную или полную сборку мусора.
  2. (Ошибка распределения) или (System.gc()) — Причина сбора — Ошибка выделения указывает, что в Эдеме больше не осталось места для размещения наших объектов .
  3. 279616K->146232K — Занятая память кучи до и после GC соответственно (разделены стрелкой)
  4. (1013632K) — Текущая емкость кучи
  5. 0,3318607 сек — продолжительность события GC в секундах.

Таким образом, если мы возьмем первую строку, 279616K->146232K(1013632K) означает, что GC уменьшил занимаемую память кучи с 279616K до 146232K . Емкость кучи во время сборки мусора составляла 1013632 КБ , а сборка мусора заняла 0,3318607 секунд.

Однако, несмотря на то, что простой формат журнала GC может быть полезен, он предоставляет ограниченную информацию. Например, мы не можем сказать, переместил ли GC какие-либо объекты из молодого поколения в старое или каков был общий размер молодого поколения до и после каждой коллекции .

По этой причине подробное ведение журнала сборщика мусора более полезно, чем простое.

4. Активация «детального» ведения журнала сборщика мусора​

Чтобы активировать подробное ведение журнала сборщика мусора, мы используем аргумент -XX:+PrintGCDetails . Это даст нам более подробную информацию о каждом сборщике мусора, например:

  • Размер молодого и старшего поколения до и после каждого 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 в Young Generation​

Мы начнем с анализа новых частей в минорном сборщике мусора:

  • [GC (ошибка размещения) [DefNew: 279616K->34944K(314560K), 0,3626923 с] 279616K->146232K(1013632K), 0,3627492 с][Times: user=0,33 sys=0,03, real=0,36 с]

Как и прежде, разобьем строки на части:

  1. DefNew — имя используемого сборщика мусора. Это не столь очевидное название означает однопоточный сборщик мусора «отметить-копировать-остановить-мир» и использовать его для очистки молодого поколения.
  2. 279616K->34944K — Использование молодого поколения до и после сбора
  3. (314560K) — Общий размер Молодого поколения
  4. 0,3626923 сек — продолжительность в секундах
  5. [Times: user=0,33 sys=0,03, real=0,36 с] — продолжительность события GC, измеренная в разных категориях.

Теперь давайте объясним различные категории:

  • user — общее время ЦП, которое было потреблено сборщиком мусора.
  • sys — время, потраченное на вызовы ОС или ожидание системных событий.
  • реальный — это все прошедшее время, включая временные интервалы, используемые другими процессами.

Поскольку мы запускаем наш пример с помощью последовательного сборщика мусора, который всегда использует только один поток, реальное время равно сумме пользовательского и системного времени.

5.2. Интерпретация полного GC​

В этом предпоследнем примере мы видим, что для основной коллекции (Full GC), которая была запущена нашим системным вызовом, использовался сборщик Tenured .

Последняя часть дополнительной информации, которую мы видим, — это разбивка по тому же шаблону для Metaspace :

[Metaspace: 2624K->2624K(1056768K)], 0.5580738 secs]

Метапространство — это новое пространство памяти , представленное в Java 8 и являющееся областью собственной памяти.

5.3. Анализ разбивки кучи Java​

Заключительная часть выходных данных включает разбивку кучи, включая сводку объема памяти для каждой части памяти .

Мы видим, что пространство Eden занимало 35%, а Tenured — 52%. Также включена сводка по пространству метаданных и пространству классов.

Из приведенных выше примеров мы теперь можем точно понять, что происходило с потреблением памяти внутри JVM во время событий GC.

6. Добавление информации о дате и времени​

Ни один хороший журнал не будет полным без информации о дате и времени.

Эта дополнительная информация может быть очень полезна, когда нам нужно сопоставить данные журнала сборщика мусора с данными из других источников, или она может просто облегчить поиск.

Мы можем добавить следующие два аргумента при запуске нашего приложения, чтобы информация о дате и времени отображалась в наших журналах:

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

Каждая строка теперь начинается с абсолютной даты и времени, когда она была написана, за которой следует отметка времени, отражающая реальное время в секундах, прошедшее с момента запуска JVM:

2018-12-11T02:55:23.518+0100: 2.601: [GC (Allocation ...

Обратите внимание, что эти флаги настройки были удалены в Java 9. Новая альтернатива:

-Xlog:gc*::time

7. Запись в файл​

Как мы уже видели, по умолчанию журнал сборщика мусора записывается в стандартный вывод . Более практичным решением является указание выходного файла.

Мы можем сделать это, используя аргумент -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=<level> для изменения уровня журнала. Например, чтобы просмотреть все журналы уровня отладки:

-Xlog:gc=debug

Как мы видели ранее, мы можем изменить назначение вывода с помощью синтаксиса -Xlog:gc=<level>:<output> . По умолчанию вывод — stdout , но мы можем изменить его на stderr или даже в файл:

-Xlog:gc=debug:file=gc.txt

Кроме того, можно добавить еще несколько полей в вывод с помощью декораторов. Например:

-Xlog:gc=debug::pid,time,uptime

Здесь мы печатаем идентификатор процесса, время безотказной работы и текущую отметку времени в каждом операторе журнала.

Дополнительные примеры унифицированного ведения журналов JVM см. в стандарте JEP 158 .

9. Инструмент для анализа журналов сборщика мусора​

Анализ журналов GC с помощью текстового редактора может занять много времени и быть довольно утомительным. В зависимости от версии JVM и используемого алгоритма GC формат журнала GC может отличаться.

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

Обязательно ознакомьтесь с Universal GC Log Analyzer !

10. Заключение​

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

Во-первых, мы начали с того, что рассказали, что такое подробная сборка мусора и почему мы можем захотеть ее использовать. Затем мы рассмотрели несколько примеров с использованием простого Java-приложения. Мы начали с включения ведения журнала GC в его простейшей форме, а затем рассмотрели несколько более подробных примеров и то, как интерпретировать вывод.

Наконец, мы изучили несколько дополнительных параметров для регистрации информации о времени и дате, а также способы записи информации в файл журнала.

Примеры кода можно найти на GitHub .