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

«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. в объект карты. Затем мы делаем явный вызов сборщику мусора, используя System.gc().

Наконец, мы удаляем 2 миллиона экземпляров String с карты. Мы также явно используем System.out.println, чтобы упростить интерпретацию вывода.

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

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

Давайте начнем с запуска нашей программы и включения подробного сбора мусора с помощью наших начальных аргументов 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. .

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

Прежде всего, мы видим, что состоялось четыре сбора, один Полный GC и три очистки Young Generation.

3.2. Подробный вывод в деталях

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

GC or Full GC – The type of Garbage Collection, either GC or Full GC to distinguish a minor or full garbage collection
(Allocation Failure) or (System.gc()) – The cause of the collection – Allocation Failure indicates that no more space was left in Eden to allocate our objects
279616K->146232K – The occupied heap memory before and after the GC, respectively (separated by an arrow)
(1013632K) – The current capacity of the heap
0.3318607 secs – The duration of the GC event in seconds

Таким образом, если мы возьмем первую строку, 279616K-\u003e146232K(1013632K) означает, что Сборщик мусора уменьшил занимаемую память кучи с 279 616 КБ до 146 232 КБ. Емкость кучи во время сборки мусора составляла 1013632 КБ, а сборка мусора заняла 0,3318607 секунд.

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

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

4. Активация «подробного» ведения журнала GC

Чтобы активировать подробное ведение журнала GC, мы используем аргумент -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:

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

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

DefNew – Name of the garbage collector used. This not so obvious name stands for the single-threaded mark-copy stop-the-world garbage collector and is what is used to clean the Young generation
279616K->34944K – Usage of the Young generation before and after collection
(314560K) – The total size of the Young generation
0.3626923 secs – The duration in seconds
[Times: user=0.33 sys=0.03, real=0.36 secs] – Duration of the GC event, measured in different categories

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

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

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

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

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

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

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

5.3. Анализ кучи Java

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

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

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

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

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

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

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

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

-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps

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

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

7. Регистрация в файл

-Xlog:gc*::time

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

Мы можем сделать это, используя аргумент -Xloggc:\u003cfile\u003e, где file — это абсолютный путь к нашему выходному файлу: новая единая регистрация. Чтобы быть более конкретным, теперь альтернатива для ведения журнала в файл:

8. Java 9: унифицированное ведение журнала JVM

-Xloggc:/path/to/file/gc.log

Начиная с Java 9, большинство флагов настройки, связанных с GC, устарели в пользу унифицированный параметр ведения журнала -Xlog:gc. Однако параметр —verbose:gc по-прежнему работает в Java 9 и более новых версиях.

-Xlog:gc:/path/to/file/gc.log

«Например, начиная с Java 9 эквивалентом флага -verbose:gc в новой унифицированной системе ведения журналов является:

При этом все журналы GC информационного уровня будут записываться в стандартный вывод. Также можно использовать синтаксис -Xlog:gc=\u003clevel\u003e для изменения уровня журнала. Например, чтобы просмотреть все журналы уровня отладки:

Как мы видели ранее, мы можем изменить назначение вывода с помощью синтаксиса -Xlog:gc=\u003clevel\u003e:\u003coutput\u003e. По умолчанию выводится stdout, но мы можем изменить его на stderr или даже в файл:

-Xlog:gc

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

-Xlog:gc=debug

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

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

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

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

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

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

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

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

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

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

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

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

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

The code examples can be found over on GitHub.

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

Spring на русском

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

«1. Обзор

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

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

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

3.1. Основное понимание подробного вывода

3.2. Подробный вывод в деталях

4. Активация «подробного» ведения журнала GC

5. Интерпретация «подробного» подробного вывода

5.1. Интерпретация второстепенного GC в Young Generation

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

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

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

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

«Например, начиная с Java 9 эквивалентом флага -verbose:gc в новой унифицированной системе ведения журналов является:

Добавить комментарий Отменить ответ