#deepjava #otus
О чем говорят логи 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, на которых исполнялась сборка.
О чем говорят логи 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, на которых исполнялась сборка.