Версия JDK, используемая в этой статье:
java version "1.8.0_144"
Java(TM) SE Runtime Environment (build 1.8.0_144-b01)
Java HotSpot(TM) 64-Bit Server VM (build 25.144-b01, mixed mode)
1. Параметры журнала сборщика мусора
К основным параметрам настройки журнала формата JVM GC относятся следующие 8:
-XX:+PrintGC 输出简要GC日志
-XX:+PrintGCDetails 输出详细GC日志
-Xloggc:gc.log 输出GC日志到文件
-XX:+PrintGCTimeStamps 输出GC的时间戳（以JVM启动到当期的总时长的时间戳形式）
-XX:+PrintGCDateStamps 输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 在进行GC的前后打印出堆的信息
-verbose:gc
-XX:+PrintReferenceGC 打印年轻代各个引用的数量以及时长
В этой статье предполагается, что читатель уже знаком со структурами памяти JVM.
1.1 -XX:+PrintGC и -verbose:gc
Если вы хотите включить информацию журнала GC, вы можете установить любой из следующих параметров:
-XX:+PrintGC
-XX:+PrintGCDetails
-Xloggc:gc.log
Если только установить-XX:+PrintGCТогда распечатанный лог выглядит так:
[GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
1,GCОбозначает YGC (Молодой GC)
2,Allocation FailureУказывает тип отказа
3.68896K->5080KУказывает, что молодое поколение уменьшено с 68896К до 5080К.
4.256000KУказывает размер всей кучи
5.0.0041139 secsУказывает общее время, проведенное в этом GC
В JDK 8,-verbose:gcда -XX:+PrintGCПсевдоним, формат журнала эквивалентен: -XX:+PrintGC, .
Но вJDK 9В -XX:+PrintGC помечен какdeprecated.
-verbose:gcстандартный вариант,-XX:+PrintGCэто экспериментальный вариант, рекомендуемый-verbose:gcзаменять-XX:+PrintGC
Ссылаться на:Difference between -XX:+PrintGC and -verbose:gc
1.2 -XX:+PrintGCDetails
[GC (Allocation Failure) [PSYoungGen: 53248K->2176K(59392K)] 58161K->7161K(256000K), 0.0039189 secs] [Times: user=0.02 sys=0.01, real=0.00 secs]
1,GCОбозначает YGC (Молодой GC)
2,Allocation FailureУказывает тип отказа
3. PSYoungGen представляет численность молодого поколения
4.53248K->2176KУказывает, что молодое поколение занимает53248Kсокращено до2176K
5.59392KУказывает размер молодой полосы
6.58161K->7161KУказывает, что вся куча занимает от58161Kсокращено до7161K
7.256000KУказывает размер всей кучи
8. 0,0039189 секунд указывает общее время, проведенное в этом сборщике мусора.
9, [Times: user=0.02 sys=0.01, real=0.00 secs]Соответственно, пользовательский режим занимал время, время ядра, реальное время.
Время округляется до двух знаков после запятой.
1.3 -XX:+PrintGCTimeStamps
1.963: [GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
Если вы добавите-XX:+PrintGCTimeStampsТогда в журнале будет только одна отметка времени больше, чем та, что была представлена в версии 1.1:1.963, Это означает, что от запуска JVM до печати времени GC прошло 1,963 секунды.
1.4 -XX:+PrintGCDateStamps
2019-03-05T16:56:15.108+0800: [GC (Allocation Failure) 61805K->9849K(256000K), 0.0041139 secs]
Если вы добавите-XX:+PrintGCDateStampsТогда в журнале будет только одна дата и время больше, чем в версии 1.1:2019-03-05T16:56:15.108+0800, время, указывающее момент печати GC, равно2019-03-05T16:56:15.108+0800. +0800 означает восточный 8-й округ.
1.5 -XX:+PrintHeapAtGC
После включения этого параметра
Используйте следующие параметры-verbose:gc -XX:+PrintHeapAtGC -Xmn64M -Xms256M -Xmx256M
Журнал печати выглядит следующим образом:
{Heap before GC invocations=1 (full 0):
PSYoungGen total 57344K, used 49152K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
eden space 49152K, 100% used [0x00000000fc000000,0x00000000ff000000,0x00000000ff000000)
from space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
to space 8192K, 0% used [0x00000000ff000000,0x00000000ff000000,0x00000000ff800000)
ParOldGen total 196608K, used 0K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
object space 196608K, 0% used [0x00000000f0000000,0x00000000f0000000,0x00000000fc000000)
Metaspace used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
class space used 888K, capacity 986K, committed 1024K, reserved 1048576K
[GC (Allocation Failure) 49152K->2416K(253952K), 0.0030218 secs]
Heap after GC invocations=1 (full 0):
PSYoungGen total 57344K, used 2400K [0x00000000fc000000, 0x0000000100000000, 0x0000000100000000)
eden space 49152K, 0% used [0x00000000fc000000,0x00000000fc000000,0x00000000ff000000)
from space 8192K, 29% used [0x00000000ff000000,0x00000000ff258020,0x00000000ff800000)
to space 8192K, 0% used [0x00000000ff800000,0x00000000ff800000,0x0000000100000000)
ParOldGen total 196608K, used 16K [0x00000000f0000000, 0x00000000fc000000, 0x00000000fc000000)
object space 196608K, 0% used [0x00000000f0000000,0x00000000f0004000,0x00000000fc000000)
Metaspace used 7901K, capacity 8264K, committed 8448K, reserved 1056768K
class space used 888K, capacity 986K, committed 1024K, reserved 1048576K
}
Отсюда видно, что до и после печати следующие логи
[GC (Allocation Failure) 49152K->2416K(253952K), 0.0030218 secs]
Печатается подробная информация журнала
вызовы указывают количество GC, каждый GC увеличивается на единицу, а вызовы до и после каждого GC равны
1,Heap before GC invocations=1Указывает состояние кучи памяти перед первым вызовом GC
2,{Heap before GC invocations=1 (full 0):Указывает состояние кучи памяти после первого вызова GC
1.6 -Xloggc:gc.log
Если этот параметр используется-XloggcПо умолчанию включены следующие два параметра
-XX:+PrintGC -XX:+PrintGCTimeStamps
Если параметры запуска следующие:-Xloggc:gc.log -Xmn64M -Xms256M -Xmx256MФормат журнала следующий
0.318: [GC (Allocation Failure) 49152K->2384K(253952K), 0.0038675 secs]
gc.logВы также можете указать абсолютный путь.
Версия JDK и параметры запуска системы также по умолчанию печатаются в начале gc.log.
Java HotSpot(TM) 64-Bit Server VM (25.144-b01) for linux-amd64 JRE (1.8.0_144-b01), built on Jul 21 2017 21:57:33 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 16287104k(1657700k free), swap 16636924k(15826632k free)
CommandLine flags: -XX:InitialHeapSize=268435456 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=67108864 -XX:NewSize=67108864 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC
1.7 -XX:+PrintReferenceGC
Этот параметр -XX:+PrintReferenceGC может распечатать количество SoftReference, WeakReference, FinalReference, PhantomReference, JNI Weak Reference и продолжительность очистки, что может быть полезно при настройке YGC.
[GC (Allocation Failure) [SoftReference, 0 refs, 0.0000119 secs][WeakReference, 499 refs, 0.0000370 secs][FinalReference, 1045 refs, 0.0002313 secs][PhantomReference, 0 refs, 0 refs, 0.0000039 secs][JNI Weak Reference, 0.0000290 secs][PSYoungGen: 53456K->4880K(57344K)] 53496K->4928K(253952K), 0.0037199 secs] [Times: user=0.02 sys=0.01, real=0.01 secs]
Для получения подробной информации, пожалуйста, обратитесь к реальному бою Чжан Сяолана:Практика оптимизации Young GC (связанная с FinalReference)
2. Подробный анализ логов CMS GC
[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs] [Times: user=0.57 sys=0.00, real=5.09 secs]
[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Журнал CMS разделен на два STW (stop the world)
соответственноinit remark(1) сremark(7) Два этапа. Как правило, это занимает примерно в 10 раз больше времени, чем YGC (личный опыт).
(1),[GC (CMS Initial Mark) [1 CMS-initial-mark: 19498K(32768K)] 36184K(62272K), 0.0018083 secs][Times: user=0.01 sys=0.00, real=0.01 secs]
Это будет STO (Stop The World).На данный момент емкость старости составляет 32768К, а метка инициализации начнется при использовании 19498К. Кропотливый.
(2),[CMS-concurrent-mark-start]
Начинается этап параллельной маркировки
(3),[CMS-concurrent-mark: 0.011/0.011 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
Параллельная фаза маркировки требует времени.
(4),[CMS-concurrent-preclean-start]
Параллельная фаза предварительной очистки также выполняется одновременно с пользовательским потоком. Виртуальная машина ищет объекты, недавно введенные в старое поколение на этапе параллельной маркировки (могут быть некоторые объекты изКайнозойповышены до старого поколения или некоторые объекты выделены старому поколению). При повторном сканировании работа по «перемаркировке» следующего этапа сокращается, потому что следующий этап остановит Мир.
(5),[CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Параллельная фаза предварительной очистки требует времени.
(6),[CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time [CMS-concurrent-abortable-preclean: 0.558/5.093 secs][Times: user=0.57 sys=0.00, real=5.09 secs]
Параллельная прерываемая фаза предварительной очистки выполняется между параллельной предварительной очисткой и примечанием до тех пор, пока не будет достигнуто желаемое использование пространства eden. Этот этап был добавлен, чтобы избежать очистки мусора сразу после этапа замечаний.
(7),[GC (CMS Final Remark) [YG occupancy: 16817 K (29504 K)][Rescan (parallel) , 0.0021918 secs][weak refs processing, 0.0000245 secs][class unloading, 0.0044098 secs][scrub symbol table, 0.0029752 secs][scrub string table, 0.0006820 secs][1 CMS-remark: 19498K(32768K)] 36316K(62272K), 0.0104997 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
Будет ли STW (Stop The World), этап сбора, на этом этапе будут отмечены все выжившие объекты в старости, включая измененные или вновь созданные эталонные объекты на этапе одновременной маркировки.
(8),[CMS-concurrent-sweep-start]
Начинается фаза параллельной очистки, которая выполняется одновременно с пользовательским потоком.
(9),[CMS-concurrent-sweep: 0.007/0.007 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
Время, прошедшее до завершения параллельной фазы очистки.
(10),[CMS-concurrent-reset-start]
Начать одновременный сброс. На этом этапе структуры данных, относящиеся к CMS, повторно инициализируются, чтобы следующий цикл мог пройти нормально.
(11),[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Прошедшее время одновременного сброса, прошедшее время.
Ссылаться на:
Geek-Yan: Заметки об исследовании JVM (4) Подробное объяснение журнала CMS GC
3. Сборщик мусора G1
Его рекомендуется использовать, когда куча памяти больше 6G, это рекомендация официального сайта.
В-четвертых, настройка GC
Следующие параметры используются для настройки производительности JVM GC.
4.1 -Xmn
Рекомендуемый размер официального сайта нового поколения:3/8, если параметр слишком мал, например1/10会Привести кMinor GCиMajor GCповышенная частота.
4.2 -XX:MaxTenuringThreshold=n
Размер n находится в интервале [0, 15].Если он больше 15, JDK7 по умолчанию будет равен 15, а JDK 8 начнет сообщать об ошибке.
5. Часто задаваемые вопросы
1. Сбой параллельного режима
Происходит во время работы CMS GC. Подробнее см.:
Настройка JVM — проблема с длинной паузой сборщика мусора и ее решения
Пессимистическая стратегия для GC
2. Продвижение не удалось
Происходит во время Minor GC