О чем говорят логи Garbage Collector?
Наверняка вы слышали, что сборщик мусора в Java может оказывать значительное влияние на производительность приложения. Многое может зависеть от типа сборщика и его настройки. Есть много инструментов для того, чтобы мониторить различные параметры сборки, но иногда достаточно внимательно посмотреть на логи, которые пишет GC. В этой заметке я расскажу, как выглядят логи, которые пишет сборщик мусора и что с помощью них можно понять о работе вашего приложения. Для начала, нужно запустить JVM, указав специальные параметры:
«-XX:+PrintGCDetails» — печатать детали о событиях сборки мусора
«-XX:+PrintGCDateStamps» — также печатать timestamp этих событий
«-Xloggc:/home/otus/gc.log» — опционально можно указать, в какой файл будут писаться логи, чтобы отделить их от логов вашего приложения.
Сборщики мусора SerialGC, ParallelGC, ConcurrentMarkSweepGC (CMS) разбивают память (хип) java-приложения на несколько регионов. Это «Eden+Survivor1+Survivor2» — молодое поколение и Tenured — старое поколение. Сборщик GC1 устроен иначе и его стоит рассматривать отдельно.
Сборки мусора могут происходить только в молодом поколении — Minor GC или во всех регионах — FullGC. Давайте посмотрим на логи на примере «ParallelGC (-XX:+UseParallelGC)».
В этих логах отображено 3 сборки мусора, сначала 2 minor, затем full:
«2017-09-17T21:03:30.200+0300: 0,449: [GC (Allocation Failure) [PSYoungGen: 3662K→336K(4608K)] 3662K→3408K(15872K), 0,0020199 secs] [Times: user=0,01 sys=0,00, real=0,01 secs]
2017-09-17T21:03:30.506+0300: 0,755: [GC (Allocation Failure) [PSYoungGen: 3652K→400K(4608K)] 6724K→6544K(15872K), 0,0021768 secs] [Times: user=0,01 sys=0,00, real=0,00 secs]
017-09-17T21:03:30.815+0300: 1,064: [Full GC (Ergonomics) [PSYoungGen: 400K→0K(4608K)] [ParOldGen: 9216K→9581K(18944K)] 9616K→9581K(23552K), [Metaspace: 3570K→3570K(1056768K)], 0,0047284 secs] [Times: user=0,00 sys=0,00, real=0,01 secs]»
«2017-09-17T21:03:30.200+0300» — сперва идет timestamp — абсолютное время, когда сборка была начата, затем время относительно старта приложения (0,449).
GC (AllocationFailure) — указывает, что это минорная сборка, при полной сборке будет указано Full GC. Причина начала сборки: не удалось выделить (allocate) место под новый объект.
PSYoungGen — тип сборщика. PSYoungGen — это сборка молодого поколения в ParallelGC. Также вы можете встретить DefNew — сборка молодого поколения в SerialGC, ParNew — сборка молодого поколения CMS.
Дальше идет самая интересная с практической точки зрения часть — занятая память до и после сборки по регионам:
«[PSYoungGen: 3662K→336K(4608K)]» — В молодом поколении до сборки было 3662K, после — 336K. Всего в регионе доступно памяти — 4608K.
«3662K→3408K(15872K)» — Статистика по всему хипу, доступно 15872K. И здесь мы видим интересный момент, что в молодом поколении освободилось 3326K, а общее место в хипе уменьшилось только на 3662 — 3408 = 254К. Это означает, что часть объектов были перемещены из молодого поколения в старое (promoted).
Сборка заняла 0,0020199 secs.
Для FullGC в логах видно статистику по всем регионам памяти, так как сборка запускается и в молодом и в старом поколении.
«[PSYoungGen: 400K→0K(4608K)] [ParOldGen: 9216K→9581K(18944K)] 9616K→9581K(23552K), [Metaspace: 3570K→3570K(1056768K)], 0,0047284 secs]»
«[Times: user=0,01 sys=0,00, real=0,01 secs]»
User — user-space время (операции вне ядра ОС), затраченное на GC. Sys — kernel-space — время, затраченное на системные вызовы ОС. Real — реальное время от начала и до конца сборки мусора. В нем учитывается, то время, пока процесс был прерван ОС или заблокирован (например, на IO).
При использовании параллельной сборки User-space время может быть больше чем real-time, потому что user-space будет суммироваться по всем CPU, на которых исполнялась сборка.
Вооружившись этими знаниями, вы сможете в рантайме смотреть за поведением GC и определить, не выросли ли паузы или количество FullGC. Как используется память вашего приложения и как объекты перемещаются между регионами памяти. Понимание этих процессов дает возможность более вдумчиво подойт
Наверняка вы слышали, что сборщик мусора в Java может оказывать значительное влияние на производительность приложения. Многое может зависеть от типа сборщика и его настройки. Есть много инструментов для того, чтобы мониторить различные параметры сборки, но иногда достаточно внимательно посмотреть на логи, которые пишет GC. В этой заметке я расскажу, как выглядят логи, которые пишет сборщик мусора и что с помощью них можно понять о работе вашего приложения. Для начала, нужно запустить JVM, указав специальные параметры:
«-XX:+PrintGCDetails» — печатать детали о событиях сборки мусора
«-XX:+PrintGCDateStamps» — также печатать timestamp этих событий
«-Xloggc:/home/otus/gc.log» — опционально можно указать, в какой файл будут писаться логи, чтобы отделить их от логов вашего приложения.
Сборщики мусора SerialGC, ParallelGC, ConcurrentMarkSweepGC (CMS) разбивают память (хип) java-приложения на несколько регионов. Это «Eden+Survivor1+Survivor2» — молодое поколение и Tenured — старое поколение. Сборщик GC1 устроен иначе и его стоит рассматривать отдельно.
Сборки мусора могут происходить только в молодом поколении — Minor GC или во всех регионах — FullGC. Давайте посмотрим на логи на примере «ParallelGC (-XX:+UseParallelGC)».
В этих логах отображено 3 сборки мусора, сначала 2 minor, затем full:
«2017-09-17T21:03:30.200+0300: 0,449: [GC (Allocation Failure) [PSYoungGen: 3662K→336K(4608K)] 3662K→3408K(15872K), 0,0020199 secs] [Times: user=0,01 sys=0,00, real=0,01 secs]
2017-09-17T21:03:30.506+0300: 0,755: [GC (Allocation Failure) [PSYoungGen: 3652K→400K(4608K)] 6724K→6544K(15872K), 0,0021768 secs] [Times: user=0,01 sys=0,00, real=0,00 secs]
017-09-17T21:03:30.815+0300: 1,064: [Full GC (Ergonomics) [PSYoungGen: 400K→0K(4608K)] [ParOldGen: 9216K→9581K(18944K)] 9616K→9581K(23552K), [Metaspace: 3570K→3570K(1056768K)], 0,0047284 secs] [Times: user=0,00 sys=0,00, real=0,01 secs]»
«2017-09-17T21:03:30.200+0300» — сперва идет timestamp — абсолютное время, когда сборка была начата, затем время относительно старта приложения (0,449).
GC (AllocationFailure) — указывает, что это минорная сборка, при полной сборке будет указано Full GC. Причина начала сборки: не удалось выделить (allocate) место под новый объект.
PSYoungGen — тип сборщика. PSYoungGen — это сборка молодого поколения в ParallelGC. Также вы можете встретить DefNew — сборка молодого поколения в SerialGC, ParNew — сборка молодого поколения CMS.
Дальше идет самая интересная с практической точки зрения часть — занятая память до и после сборки по регионам:
«[PSYoungGen: 3662K→336K(4608K)]» — В молодом поколении до сборки было 3662K, после — 336K. Всего в регионе доступно памяти — 4608K.
«3662K→3408K(15872K)» — Статистика по всему хипу, доступно 15872K. И здесь мы видим интересный момент, что в молодом поколении освободилось 3326K, а общее место в хипе уменьшилось только на 3662 — 3408 = 254К. Это означает, что часть объектов были перемещены из молодого поколения в старое (promoted).
Сборка заняла 0,0020199 secs.
Для FullGC в логах видно статистику по всем регионам памяти, так как сборка запускается и в молодом и в старом поколении.
«[PSYoungGen: 400K→0K(4608K)] [ParOldGen: 9216K→9581K(18944K)] 9616K→9581K(23552K), [Metaspace: 3570K→3570K(1056768K)], 0,0047284 secs]»
«[Times: user=0,01 sys=0,00, real=0,01 secs]»
User — user-space время (операции вне ядра ОС), затраченное на GC. Sys — kernel-space — время, затраченное на системные вызовы ОС. Real — реальное время от начала и до конца сборки мусора. В нем учитывается, то время, пока процесс был прерван ОС или заблокирован (например, на IO).
При использовании параллельной сборки User-space время может быть больше чем real-time, потому что user-space будет суммироваться по всем CPU, на которых исполнялась сборка.
Вооружившись этими знаниями, вы сможете в рантайме смотреть за поведением GC и определить, не выросли ли паузы или количество FullGC. Как используется память вашего приложения и как объекты перемещаются между регионами памяти. Понимание этих процессов дает возможность более вдумчиво подойт