предисловие
В последнее время я столкнулся с несколькими системами с относительно большим временем молодой сборщик мусора.Когда молодой сборщик мусора длинный, нагрузка на систему также увеличивается в любое время.Поэтому необходимо быть знакомым с журналом сборщика мусора и понимать некоторые общие настройки JVM.
награда
После прочтения вы должны получить следующие результаты
- Ознакомьтесь со значением каждой строчки лога Young GC (увидим).
- Понять некоторые ключевые параметры настройки GC (сбора ям).
анализ журнала
// GC原因，新生代minor GC。
2019-11-09T10:14:42.496+0800: 143830.361: [GC pause (G1 Evacuation Pause) (young)
//survivor大小及对象年龄最大值是15
Desired survivor size 67108864 bytes, new threshold 15 (max 15).
- age 1: 21372336 bytes, 21372336 total
- age 2: 5495736 bytes, 26868072 total
- age 3: 30424 bytes, 26898496 total
- age 4: 116344 bytes, 27014840 total
- age 5: 22704 bytes, 27037544 total
- age 6: 81712 bytes, 27119256 total
- age 7: 17824 bytes, 27137080 total
- age 8: 172736 bytes, 27309816 total
- age 9: 348672 bytes, 27658488 total
- age 10: 361192 bytes, 28019680 total
- age 11: 153648 bytes, 28173328 total
- age 12: 37056 bytes, 28210384 total
- age 13: 81800 bytes, 28292184 total
- age 14: 6272 bytes, 28298456 total
- age 15: 31096 bytes, 28329552 total
// 发生minor GC和full GC时，所有相关region都是要回收的。而发生并发GC时，会根据目标停顿时间动态选择部分垃圾对并多的Region回收，这一步就是选择Region。
// pending_cards是关于RSet的Card Table。
// predicted base time是预测的扫描card table时间。
143830.362: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 13047, predicted base time: 104.33 ms, remaining time: 0.00 ms, target pause time: 100.00 ms]
// 这一步是添加Region到collection set，新生代一共496个Region，16个幸存区Region，预计收集时间是3.45 ms。
143830.362: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 496 regions, survivors: 16 regions, predicted young region time: 3.45 ms]
// 这一步是对上面两步的总结。预计总收集时间107.78ms。
143830.362: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 496 regions, survivors: 16 regions, old: 0 regions, predicted pause time: 107.78 ms, target pause time: 100.00 ms]
//
2019-11-09T10:14:42.611+0800: 143830.477: [SoftReference, 0 refs, 0.0136201 secs]2019-11-09T10:14:42.625+0800: 143830.490: [WeakReference, 2 refs, 0.0165891 secs]2019-11-09T10:14:42.641+0800: 143830.507: [FinalReference, 609 refs, 0.0244947 secs]2019-11-09T10:14:42.666+0800: 143830.531: [PhantomReference, 1 refs, 331 refs, 0.0342801 secs]2019-11-09T10:14:42.700+0800: 143830.566: [JNI Weak Reference, 0.0000451 secs], 0.2087493 secs]
// Parallel Time: 并行收集任务在运行过程中引发的STW（Stop The World）时间，从新生代垃圾收集开始到最后一个任务结束，共花费93.6ms
// GC Workers: 有28个线程负责垃圾收集，通过参数-XX:ParallelGCThreads设置，这个参数的值的设置，跟CPU有关，默认值 ParallelGCThreads＝8+( Processor - 8 ) ( 5/8 )，比如40核心的机器，那么GC线程数就是28。
[Parallel Time: 93.6 ms, GC Workers: 28]
// 第一个垃圾收集线程开始工作时JVM启动后经过的时间（min）；最后一个垃圾收集线程开始工作时JVM启动后经过的时间（max）；diff表示min和max之间的差值。理想情况下，你希望他们几乎是同时开始，即diff趋近于0。
[GC Worker Start (ms): Min: 143830362.2, Avg: 143830362.7, Max: 143830363.5, Diff: 1.4]
// 扫描root集合（线程栈、JNI、全局变量、系统表等等）花费的时间，扫描root集合是垃圾收集的起点，尝试找到是否有root集合中的节点指向当前的收集集合（CSet）
[Ext Root Scanning (ms): Min: 2.3, Avg: 8.2, Max: 16.0, Diff: 13.6, Sum: 229.4]
// 每个分区都有自己的RSet，用来记录其他分区指向当前分区的指针，如果RSet有更新，G1中会有一个post-write barrier管理跨分区的引用——新的被引用的card会被标记为dirty，并放入一个日志缓冲区，如果这个日志缓冲区满了会被加入到一个全局的缓冲区，在JVM运行的过程中还有线程在并发处理这个全局日志缓冲区的dirty card。Update RS表示允许垃圾收集线程处理本次垃圾收集开始前没有处理好的日志缓冲区，这可以确保当前分区的RSet是最新的。
[Update RS (ms): Min: 0.0, Avg: 1.4, Max: 4.0, Diff: 4.0, Sum: 39.4]
// Processed Buffers，这表示在Update RS这个过程中处理多少个日志缓冲区。
[Processed Buffers: Min: 0, Avg: 17.0, Max: 67, Diff: 67, Sum: 475]
//扫描每个新生代分区的RSet，找出有多少指向当前分区的引用来自CSet。
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.6]
// 扫描代码中的root节点（局部变量）花费的时间
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
//在疏散暂停期间，所有在CSet中的分区必须被转移疏散，Object Copy就负责将当前分区中存活的对象拷贝到新的分区。
[Object Copy (ms): Min: 0.0, Avg: 7.6, Max: 85.5, Diff: 85.4, Sum: 212.1]
//当一个垃圾收集线程完成任务时，它就会进入一个临界区，并尝试帮助其他垃圾线程完成任务（steal outstanding tasks），min表示该垃圾收集线程什么时候尝试terminatie，max表示该垃圾收集回收线程什么时候真正terminated。
[Termination (ms): Min: 0.0, Avg: 75.2, Max: 79.0, Diff: 79.0, Sum: 2106.8]
// 如果一个垃圾收集线程成功盗取了其他线程的任务，那么它会再次盗取更多的任务或再次尝试terminate，每次重新terminate的时候，这个数值就会增加
[Termination Attempts: Min: 1, Avg: 1.4, Max: 2, Diff: 1, Sum: 39]
// 垃圾收集线程在完成其他任务的时间
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.0]
// 展示每个垃圾收集线程的最小、最大、平均、差值和总共时间
[GC Worker Total (ms): Min: 91.6, Avg: 92.5, Max: 93.3, Diff: 1.7, Sum: 2590.3]
// GC Worker End：min表示最早结束的垃圾收集线程结束时该JVM启动后的时间；max表示最晚结束的垃圾收集线程结束时该JVM启动后的时间。理想情况下，你希望它们快速结束，并且最好是同一时间结束。
[GC Worker End (ms): Min: 143830455.1, Avg: 143830455.2, Max: 143830455.5, Diff: 0.4]
// 新生代GC中的一些任务
[Code Root Fixup: 0.1 ms] //释放用于管理并行垃圾收集活动的数据结构，应该接近于0，该步骤是线性执行的；
[Code Root Purge: 0.0 ms] //清理更多的数据结构，应该很快，耗时接近于0，也是线性执行
[Clear CT: 0.5 ms] //清理card table
//一些其他的拓展功能
[Other: 114.6 ms]
[Choose CSet: 0.0 ms] //选择要进行回收的分区放入CSet（G1选择的标准是垃圾最多的分区优先，也就是存活对象率最低的分区优先）
[Ref Proc: 109.9 ms] // 处理Java中的各种引用——soft、weak、final、phantom、JNI等等。
[Ref Enq: 0.6 ms] // 遍历所有的引用，将不能回收的放入pending列表
[Redirty Cards: 0.4 ms] //在回收过程中被修改的card将会被重置为dirty
[Humongous Register: 0.1 ms]// JDK8u60提供了一个特性，巨型对象可以在新生代收集的时候被回收——通过G1ReclaimDeadHumongousObjectsAtYoungGC设置，默认为true。
[Humongous Reclaim: 0.0 ms] //做下列任务的时间：确保巨型对象可以被回收、释放该巨型对象所占的分区，重置分区类型，并将分区还到free列表，并且更新空闲空间大小。
[Free CSet: 0.9 ms]// 将要释放的分区还回到free列表。
// 展示了不同代的大小变化，以及堆大小的自适应调整
// Eden: 992.0M(992.0M)->0.0B(982.0M)
（1）当前新生代收集触发的原因是Eden空间满了，分配了992M，使用了992M；
（2）所有的Eden分区都被疏散处理了，在新生代结束后Eden分区的使用大小成为了0.0B；
（3）Eden分区的大小缩小为982.0M；
// Survivors: 32.0M->42.0M：由于年轻代分区的回收处理，survivor的空间从32.0M涨到42.0M；
// Heap: 2304.3M(4096.0M)->1322.8M(4096.0M)]
（1）在本次垃圾收集活动开始的时候，堆空间整体使用量是2304.3M，堆空间的最大值是4096.0M；
（2）在本次垃圾收集结束后，堆空间的使用量是1322.8M，最大值保持不变。
[Eden: 992.0M(992.0M)->0.0B(982.0M) Survivors: 32.0M->42.0M Heap: 2304.3M(4096.0M)->1322.8M(4096.0M)]
// 本次新生代垃圾收集的时间
// user=2.81 ：垃圾收集线程在新生代垃圾收集过程中消耗的CPU时间，这个时间跟垃圾收集线程的个数有关，可能会比real time大很多；
// sys=0.17 ：内核态线程消耗的CPU时间
// real=0.21：本次垃圾收集真正消耗的时间；
[Times: user=2.81 sys=0.17, real=0.21 secs]
2019-11-09T10:14:42.705+0800: 143830.570: Total time for which application threads were stopped: 0.2183659 seconds, Stopping threads took: 0.0012684 seconds
// 当GC发生时，每个线程只有进入了SafePoint才算是真正挂起，也就是真正的停顿，这个日志的含义是整个GC过程中STW的时间，配置了-XX:+PrintGCApplicationStoppedTime这个参数才会打印这个信息。
// 重点：第一个0.0091676 seconds 是JVM启动后的秒数，第二个 0.0007286 seconds是JVM发起STW的开始到结束的时间。特别地，如果是GC引发的STW，这条内容会紧挨着出现在GC log的下面。
// 这里想搞清楚？ 请移步： https://juejin.cn/post/6844903991952801806
2019-11-09T10:14:42.795+0800: 143830.660: Total time for which application threads were stopped: 0.0091676 seconds, Stopping threads took: 0.0007286 seconds
Настройка основных параметров
Уведомление:Ниже приводится краткое введение, и чтобы углубиться в каждый параметр, потребуется час обучения.
-XX:-UseBiasedLocking
Смещенная блокировка, открытая по умолчанию в JDK1.6, попытается назначить блокировку первому потоку, который к ней обращается, отменяя синхронизированный примитив в синхронизированном блоке. Если к нему постоянно обращается только один поток, операция синхронизации успешно пропускается для повышения производительности. Но как только второй поток получит доступ к блокировке, JVM отменит предвзятую блокировку и восстановит ее до состояния разблокированного потока. хотя это всего лишь короткая пауза, но для многопоточных одновременных приложений ее отмена улучшит производительность, поэтому рекомендуется выполнять оптимизацию блокировки без смещения, когда система становится узким местом.
-XX:AutoBoxCacheMax
Integer i=3;Этот оператор имеет процесс автоматического упаковывания int в Integer. JDK по умолчанию кэширует только Integer и Long от -128 до +127. Если число превышает диапазон, новый объект Integer будет создан немедленно. В случае высокого параллелизма нельзя игнорировать потерю производительности при распаковке и упаковке, поэтому рекомендуется увеличить эту конфигурацию, например, до 2w.
-XX:ParallelGCThreads
Поскольку операция GC приостанавливает все потоки приложения, JVM должна использовать как можно больше ресурсов ЦП, чтобы минимизировать время паузы. Это означает, что по умолчанию JVM будет запускать один поток на каждый ЦП на машине, максимум до 8 одновременно.
Как только этот предел достигнут, JVM корректирует алгоритм, чтобы запускать новый поток каждые 5/8 превышения ЦП. Таким образом, общее количество потоков равно (где N представляет собой количество ядер ЦП): ParallelGCThreads = 8 + ((N - 8) * 5/8)
Иногда количество потоков, оцениваемых с помощью этого алгоритма, слишком велико. Если приложение использует небольшую кучу (скажем, 1 ГБ), работающую на машине с восемью процессорами, может быть более эффективно использовать 4 или 6 потоков для обработки кучи. На машине со 128 ЦП запуск 83 потоков сборки мусора также может быть слишком большим, если только куча, используемая системой, не достигла своего максимального предела.
-XX:+HeapDumpOnOutOfMemoryError
В случае нехватки памяти, когда JVM вот-вот умрет, выведите дамп кучи в указанный файл, но в среде контейнера (или смешанном отделе) это приведет к тому, что операция ввода-вывода на жестком диске будет выполняться полностью более 20 секунд в обычном режиме. жесткого диска, что также является полным злом соседей, влияющим на все остальные службы на том же хосте.
-XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=512m
Расширение вызовет паузу, что очень сильно повлияет на даунстрим.Саппорт уже наступал на эту яму раньше.Обязательно соблюдайте размер метапространства.Если его недостаточно,то быстро корректируйте.
-XX:+PrintGCApplicationStoppedTime
Время GC невелико, но нисходящий поток часто истекает.Это может быть не вызвано GC, но не вызвано GC, например, отменой смещенных блокировок, деоптимизацией кода и т. д., включите параметр -XX:+PrintGCApplicationStoppedTime
Примечание. Журнал точек сохранения нельзя включать постоянно:
- Вывод лога точки безопасности по умолчанию на stdout, один — опрятность лога stdout, а второй — файл, перенаправленный stdout, находится не в /dev/shm, что может быть заблокировано.
- Для некоторых очень коротких пауз, таких как отмена блокировки смещения, стоимость печати превышает стоимость самой паузы.
- Журнал точки безопасности печатается внутри точки безопасности, что само по себе увеличивает время паузы точки безопасности.
Поэтому журнал безопасности следует включать только для устранения неполадок. Если вы хотите открыть его в производственной системе, добавьте следующие четыре параметра: -XX:+UnlockDiagnosticVMOptions -XX: -DisplayVMOutput -XX:+LogVMOutput -XX:LogFile=/dev/shm/vm.log Включите диагностику (просто откройте дополнительные флаги, чтобы они были необязательными, не активируйте определенный флаг), отключите вывод журналов ВМ на стандартный вывод и вывод в отдельный файл, каталог /dev/shm (файловая система памяти).
-XX:+PerfDisableSharedMem
Лог в проекте пишется асинхронно.При высоких дисковых IO служебный лог будет сбрасываться.Вы когда-нибудь задумывались о том, что запись лога GC повлияет на производительность JVM, и повлияет ли это на время GC? Ответ Да, когда дисковый ввод-вывод высок, а кеш страниц сбрасывается, это может вызвать паузу в это время.
Ключевое внимание: если реальное время слишком велико, нормальное реальное время намного меньше пользовательского времени (около одной десятой), сбрасывает ли текущая система pageCache на диск, когда эти два условия выполняются, это может повлиять на ввод-вывод. .
-Xss
-Xss256k: за пределами кучи потоки занимают стековую память, и каждый поток по умолчанию имеет размер 1 МБ. Стек, локальные переменные, локальные переменные после скалярной подстановки и т.д. для хранения параметров вызова метода, некоторым нравится ставить небольшие точки для экономии памяти и открытия большего количества потоков. Но если памяти достаточно, не обязательно ставить маленькую, некоторые любят ставить побольше, особенно когда есть рекурсивные вызовы типа парсинга JSON, нельзя ставить слишком маленькую.
-XX:ReservedCodeCacheSize
JIT компилирует область хранения бинарного кода, больше не компилирует, по умолчанию 245m. Когда CodeCache заполнен, программа будет казаться очевидной Carton, сервисная мощность будет снижена, а JVM напечатает предупреждающее сообщение и переключится в режим только для интерпретации: JIT-компилятор устарел, байт-код больше не будет компилироваться в Машинный код. Следовательно, приложение будет продолжать работать, но скорость работы будет снижаться на количественный уровень, пока кто-нибудь не обратит внимание на эту проблему.
// 当服务极度卡顿，可以怀疑这里，可以通过反证法验证是否出现过这个日志，来确认是不是这个问题
`Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled`
-XX:+AlwaysPreTouch
Когда процесс JAVA запускается, хотя мы можем указать соответствующий размер памяти для JVM, операционная система фактически не выделяет эту память для JVM, а только когда JVM обращается к памяти, что вызовет следующие проблемы.
- Во время GC, когда объекты нового поколения нужно продвигать к старому поколению, нужна память, в это время операционная система будет фактически выделять память, что увеличит время паузы молодого GC.
- Возможно проблема с фрагментацией памяти.
Таким образом, вы можете рассмотреть возможность включения этого параметра, и служба будет напрямую открывать эту память. Настройка этого параметра зависит от фактической ситуации. Необходимо убедиться, что нет ситуации избыточного выделения и что имеется достаточно фактической памяти, которую можно выделить. к каждой услуге, например:R Большой - AlwaysPreTouch
Memory Overcommit означает, что объем памяти, обещанный операционной системой процессу, превышает фактически доступную память.Подробный анализ:Linux overcommit
-XX:+UseStringDeduplication
JVM без акцента, JVM может сэкономить место, но можно увеличить время GC.
Плюсы и минусы включения дедупликации строк XX:+UseStringDeduplication \ Разговор о дедупликации строк G1 GC
-XX:+ParallelRefProcEnabled
Параллельная обработка объектов Reference, таких как WeakReference, по умолчанию имеет значение false.Если в журнале GC нет журнала с длительным временем обработки ссылок, эффект не будет очевиден, но мы всегда хотим, чтобы JVM была максимально параллельной, так что устанавливай. Точно так же -XX:+CMSParallelInitialMarkEnabled, JDK8 был включен по умолчанию, но JDK7 с относительно низкой версией даже не поддерживает его.
Продолжение следует. . .