[转帖]GC 日志

gc,日志 · 浏览次数 : 0

小编点评

# Java GC Analysis ## GC Causes and Symptoms - **Allocation Failure:** Allocation space is insufficient for requested objects. - **OutOf Memory:** The heap is exhausted and cannot allocate more objects. - **Tenured Generation:** Objects from the old generation are continuously added to the heap. - **Concurrent Mark:** The heap is divided into multiple segments, and objects from different segments are marked concurrently. - **Metadata GC:** The heap is cleaned up to release unused memory, but the metadata cannot be removed. - **Last Ditch Collection:** Objects are released from the heap to make space for other objects. ## Symptoms of GC Problems - Excessive memory usage. - Evacuation failures. - Out of memory errors. - Tenured generation problems. - Concurrent mark problems. - Metadata GC problems. - Last ditch collection issues. ## GC Analysis Tools - **Jmap:** A tool for analyzing heap and memory structures. - **Metaspace:** A tool for analyzing memory allocation and collection. - **GC Analyzer:** A tool for analyzing the GC behavior of applications. - **Visual GC:** A tool for analyzing the GC behavior of applications. ## Tips for GC Analysis - Use Jmap to analyze the heap and memory structures. - Use Metaspace to analyze memory allocation and collection. - Use GC Analyzer to analyze the GC behavior of applications. - Use Visual GC to analyze the GC behavior of applications. - Identify the root cause of GC problems. - Use profiling tools to identify where GC occurs. - Use tools for analyzing the GC behavior of applications.

正文

https://www.xjx100.cn/news/188814.html?action=onClick

 

垃圾回收器的发展历史

1999年:随JDK1.3.1一起来的串行方式Serial GC(第一款GC),ParNew GC是SerialGC的多线程版本。
2002年:2月26日,Parallel GC和Concurrent Mark Sweep GC(即CMS)跟随JDK1.4.2一起发布。Parallel GC在JDK6之后成为Hotspot默认GC。
2012年:在JDK1.7u4中,G1可用。
2017年:JDK9中G1成为默认垃圾回收器,以替代CMS.
2018年:3月,JDK10中G1的并行完整垃圾回收,实现并行性能改善最坏情况的延迟。
9月,JDK11发布,引入Epsilon GC,又称为“No-Op无操作”回收器,同时引入ZGC:可伸缩的低延迟回收器(Experimental)
2019年:3月,JDK12发布。增加G1,自动返回未使用堆内存给操作系统;同时,引入Shenandoah GC:地停顿时间的GC(Experimental)
9月,JDK13发布。增强ZGC,自动返回未使用堆内存给操作系统。
2020年:3月,JDK14发布。删除CMS,扩展ZGC,在mac和windows的应用。

**串行GC:**采用单线程回收垃圾,用户线程处于等待状态,适合于堆内存空间比较小和个人小项目
**并行GC:**多条垃圾收集线程并行工作,但用户线程仍然处于等待状态。
**并发GC:**用户线程和垃圾收集线程同时执行,他们运行于不同的CPU上。(不一定是并行,可能是交替执行)

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-sAHmVBKs-1680790296560)(https://note.youdao.com/yws/res/16776/WEBRESOURCE65846b401e6666c3ff75e5b9ed78133e)]

-XX:+UseSerialGC:开启此参数使用serial & serial old搜集器(client模式默认值)。

 

-XX:+UseParNewGC:开启此参数使用ParNew & serial old搜集器(不推荐)

 

-XX:+UseConcMarkSweepGC:开启此参数使用ParNew & CMS(serial old为替补)搜集器

-XX:+UseParallelGC:开启此参数使用parallel scavenge & parallel old搜集器(server模式默认值)

-XX:+UseParallelOldGC:开启此参数在年老代使用parallel old搜集器(该参数在JDK1.5之后已无用)。

SerialGC

[DefNew: 139776K->17472K(157248K), 0.0164545 secs] 139776K->45787K(506816K), 0.0165501 secs] [Times: user=0.00 sys=0.02, real=0.02 secs] 2021-09-09T14:44:04.853+0800: 0.203: [GC (Allocation Failure) 2021-09-09T14:44:04.853+0800: 0.203: [DefNew: 157248K->17471K(157248K), 0.0192998 secs] 185563K->84401K(506816K), 0.0193485 secs] [Times: user=0.02 sys=0.01, real=0.02 secs]
2021-09-09T20:43:46.841+0800: 0.375: [Full GC (Allocation Failure) 2021-09-09T20:43:46.841+0800: 0.375: 
[Tenured: 174631K->174502K(174784K), 0.0228937 secs] 252975K->195967K(253440K),
[Metaspace: 2760K->2760K(1056768K)], 0.0230051 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

收集器的名称为 DefNew(Default New Generation) 老年代为 Tenured

ParallelGC

2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs] 2021-09-09T22:08:14.214+0800: 0.403: 
[Full GC (Ergonomics) 
[PSYoungGen: 21497K->0K(153088K)] 
[ParOldGen: 333673K->249484K(349696K)] 355171K->249484K(502784K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0326259 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 

收集器的名称 PsYoungGen 老年代的微 ParOldGen

UseConcMarkSweepGC

2021-09-10T10:04:53.054+0800: 0.327: [GC (CMS Initial Mark) [1 CMS-initial-mark: 205370K(349568K)] 223428K(506816K), 0.0001030 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.054+0800: 0.327: [CMS-concurrent-mark-start]
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-mark: 0.003/0.003 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.057+0800: 0.330: [CMS-concurrent-preclean-start]
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.058+0800: 0.331: [CMS-concurrent-abortable-preclean-start]
==================================中间穿插着MinorGC================================
2021-09-10T10:04:53.076+0800: 0.349: [GC (Allocation Failure) 2021-09-10T10:04:53.076+0800: 0.349: [ParNew: 157248K->17472K(157248K), 0.0156403 secs] 362618K->266214K(506816K), 0.0157138 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
2021-09-10T10:04:53.113+0800: 0.387: [GC (Allocation Failure) 2021-09-10T10:04:53.113+0800: 0.387: [ParNew: 157248K->17472K(157248K), 0.0155434 secs] 405990K->308435K(506816K), 0.0155941 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2021-09-10T10:04:53.149+0800: 0.423: [GC (Allocation Failure) 2021-09-10T10:04:53.149+0800: 0.423: [ParNew: 157074K->17472K(157248K), 0.0173170 secs] 448038K->353000K(506816K), 0.0173738 secs] [Times: user=0.05 sys=0.00, real=0.02 secs] 
==================================================================================
2021-09-10T10:04:53.167+0800: 0.440: [CMS-concurrent-abortable-preclean: 0.003/0.109 secs] [Times: user=0.17 sys=0.02, real=0.11 secs] 
----------------------------------最终标记------------------------------------
2021-09-10T10:04:53.167+0800: 0.440: [GC (CMS Final Remark) [YG occupancy: 20972 K (157248 K)]2021-09-10T10:04:53.167+0800: 0.440: [Rescan (parallel) , 0.0002117 secs]2021-09-10T10:04:53.167+0800: 0.440: [weak refs processing, 0.0000083 secs]2021-09-10T10:04:53.167+0800: 0.441: [class unloading, 0.0002509 secs]2021-09-10T10:04:53.168+0800: 0.441:[scrub symbol table, 0.0003192 secs]2021-09-10T10:04:53.168+0800: 0.441: [scrub string table, 0.0001136 secs][1 CMS-remark: 335528K(349568K)] 356500K(506816K), 0.0009630 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.168+0800: 0.441: [CMS-concurrent-sweep-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset-start]
2021-09-10T10:04:53.169+0800: 0.442: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

新生代的收集器为 ParNew 老年代就是CMS了

日志分析

2021-09-09T22:08:14.204+0800: 0.393:
[GC (Allocation Failure) 
[PSYoungGen: 153077K->21497K(153088K)] 446120K->355171K(502784K), 0.0096928 secs] [Times: user=0.05 sys=0.11, real=0.01 secs] 

网上找的一段例子

  • 2021-09-09T22:08:14.204+0800: 0.393-GC事件开始的时间点。+0800表示当前时区为东八区,这只是一个标识。0.393是GC事件相对于JVM启动时间的间隔,单位是秒
  • GC - 用来区分Minor GC还是Full GC的标志。GC表明这是一次小型GC(Minor GC),即年轻代GC
  • GC cause 。触发GC的原因、这里是 Allocation Failure。对象分配失败导致GC。这个 GC cause 后面详细分析
  • PSYoungGen:垃圾收集器的名称,这个名称表示的是在年轻代中使用的:并行的标记-复制,STW垃圾收集器
  • 153077K->21497K(153088K)表示年轻代回收前->回收后(年轻代内存大小),GC后新生代使用率为 21497K / 153088K= 14%
  • 446120K->355171K(502784K)表示堆内存回收前大小->堆内存回收后大小(堆内存大小),GC后堆内存使用率为 355171K / 502784K = 70%,使用率并不低
  • [Times: user=0.05 sys=0.11, real=0.01 secs] :GC事件的持续时间,通过三个部分衡量,user表示GC线程所消耗的总CPU时间,sys表示操作系统和系统等待事件所消耗的时间,real则表示应用程序实际暂停时间。由于并不是所有的操作过程都能全部并行,所以在并行GC中,real 的值可能会小于 user + sys 的值。四舍五入的结果

在做性能优化时,我们一般采用 real 时间来优化程序。因为最终用户只关心点击页面发出请求到页面上展示出内容所花的时间,也就是响应时间,而不关心你到底使用了多少个 GC 线程或者处理器。但并不是说 sys 和 user 两个时间不重要,当我们想通过增加 GC 线程或者 CPU 数量来减少 GC 停顿时间时,可以参考这两个时间

JVM - 一篇带你读懂 Java GC 日志(附 GC 耗时讲解)_垃圾收集器

JVM - 一篇带你读懂 Java GC 日志(附 GC 耗时讲解)_垃圾收集器_02

2021-09-09T22:08:14.214+0800: 0.403: 
[Full GC (Ergonomics) 
[PSYoungGen: 21497K->0K(153088K)] 
[ParOldGen: 333673K->249484K(349696K)] 355171K->249484K(502784K), 
[Metaspace: 2760K->2760K(1056768K)], 0.0326259 secs] [Times: user=0.31 sys=0.00, real=0.03 secs] 
  • Metaspace: 2760K->2760K(1056768K) 元空间并没有被回收掉任何对象

GC cause

JVM 参数 -XX:+PrintGCCause 来打印 gc cause

/** Copyright (c) 2002, 2013, Oracle and/or its affiliates. All rights reserved.* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.** This code is free software; you can redistribute it and/or modify it* under the terms of the GNU General Public License version 2 only, as* published by the Free Software Foundation.** This code is distributed in the hope that it will be useful, but WITHOUT* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or* FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License* version 2 for more details (a copy is included in the LICENSE file that* accompanied this code).** You should have received a copy of the GNU General Public License version* 2 along with this work; if not, write to the Free Software Foundation,* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.** Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA* or visit www.oracle.com if you need additional information or have any* questions.**/#include "precompiled.hpp"
#include "gc_interface/gcCause.hpp"const char* GCCause::to_string(GCCause::Cause cause) {switch (cause) {case _java_lang_system_gc:return "System.gc()";case _full_gc_alot:return "FullGCAlot";case _scavenge_alot:return "ScavengeAlot";case _allocation_profiler:return "Allocation Profiler";case _jvmti_force_gc:return "JvmtiEnv ForceGarbageCollection";case _gc_locker:return "GCLocker Initiated GC";case _heap_inspection:return "Heap Inspection Initiated GC";case _heap_dump:return "Heap Dump Initiated GC";case _wb_young_gc:return "WhiteBox Initiated Young GC";case _update_allocation_context_stats_inc:case _update_allocation_context_stats_full:return "Update Allocation Context Stats";case _no_gc:return "No GC";case _allocation_failure:return "Allocation Failure";case _tenured_generation_full:return "Tenured Generation Full";case _metadata_GC_threshold:return "Metadata GC Threshold";case _cms_generation_full:return "CMS Generation Full";case _cms_initial_mark:return "CMS Initial Mark";case _cms_final_remark:return "CMS Final Remark";case _cms_concurrent_mark:return "CMS Concurrent Mark";case _old_generation_expanded_on_last_scavenge:return "Old Generation Expanded On Last Scavenge";case _old_generation_too_full_to_scavenge:return "Old Generation Too Full To Scavenge";case _adaptive_size_policy:return "Ergonomics";case _g1_inc_collection_pause:return "G1 Evacuation Pause";case _g1_humongous_allocation:return "G1 Humongous Allocation";case _last_ditch_collection:return "Last ditch collection";case _last_gc_cause:return "ILLEGAL VALUE - last gc cause - ILLEGAL VALUE";default:return "unknown GCCause";}ShouldNotReachHere();
}

system.gc

调用 System.gc() 时触发
注意,调用该方法只是额外启动一个方法然后在合适的时间去执行 GC。所以它并不能保证立刻触发 GC(和JVM执行GC有关),也不能保证一定会执行 GC(和垃圾回收器有关),也不能保证触发的 GC 时 Young GC 还是 Full GC(和垃圾回收器有关)
如果想禁用显式 GC(默认不禁用):-XX:+DisableExplicitGC

 

FullGCAlot

JDK 的调试版本可以设置,用来定期触发 GC,我自己的项目中测试时提示如下异常:

ScavengeAlot

JDK 的调试版本可以设置,用来定期触发 GC,我自己的项目中测试时提示如下异常:

Allocation Profiler

使用 -Xaprof 设置运行项目,它会在 jvm 退出之前触发。 -Xaprof 选项已在 java 8 中删除

JvmtiEnv ForceGarbageCollection

JVMTI 是 Java 虚拟机所提供的 native 编程接口,用来对 Java 运行态测试和分析,常见的实现就是各种各样的 Java Agent 了
这个 GC 的产生原因,其实就是你自己强制调用 GC

GCLocker Initiated GC

当使用本地方法 JNI 函数访问 JVM 中的字符串或数组数据,为保证数据安全性和准确性,获取数据(GetStringCritical)和释放数据(ReleaseStringCritical)这段过程必须在 “critical region”(临界区)执行 如果在执行临界区这段时间发生了 GC,JVM 会阻断 GC 的发生,也会阻断其他线程进入临界区,同时调 ReleaseStringCritical。当最后一个临界区的线程退出后,JVM 再进行一个 GC,即 GCLocker Initiated GC

Heap Inspection Initiated GC

该 GC 是当你对堆进行检查时触发,使用如下命令才能出现

jmap -histo:live <pid>

Heap Dump Initiated GC

该 GC 是当你对堆进行转储时触发,使用如下命令才能出现

jmap -dump:live,format=b,file=heap.out <pid>

WhiteBox Initiated Young GC

测试时主动触发的 Young GC,需要增加 WhiteBox 的 Agent 才能使用,后边会讲 WhiteBox

Update Allocation Context Stats

原为:GCs can be initiated solely for the purpose of getting updated allocation context statistics; these GCs should be identifiable by a unique GCCause. Add a new cause “_update_allocation_context_stats”.这个 GC 仅用于获取更新的分配上下文统计信息。具体参照:JDK-8058235 : identify GCs initiated to update allocation context stats

No GC

用来指示 CMS 并发标记的阶段

Allocation Failure

Allocation Failure 表示向 Young generation(eden) 给新对象申请空间,但是 Young generation(eden) 剩余的合适空间不够所需的大小导致的 Young GC,在 G1 垃圾回收器中非常常见这个 GC

// 三个参数分别是:最大堆,初识堆,年轻代 
-Xmx
-Xms
-Xmn
// 年轻代中eden和survivor的比例,默认8:1:1,即SurvivorRatio=8,SurvivorRatio=4时意味着比例为 4:1:1
–XX:SurvivorRatio
// 年轻代和老年代比例,默认1:2
-xx:newratio

Tenured Generation Full

是针对老年代的一个 Full GC。原因是老年代的对象长期存在并不断有新的生成从而导致 Tenured Generation 满了,最后触发 GC

Metadata GC Threshold

// 初识元空间大小,默认 21MB
-XX:MetaspaceSize=128
// 最大元空间大小
-XX:MaxMetaspaceSize=128

CMS Generation Full

CMS Initial Mark

CMS Final Remark

CMS Concurrent Mark

Old Generation Expanded On Last Scavenge

Old Generation Too Full To Scavenge

Ergonomics

这种异常会发生在 Parallel Scavenge+Serial Old 的组合下,如果老生代的剩余空间少于下一次收集所需的剩余空间,那么现在就做一个 Full GC,其实就是虚拟机估算出下次分配可能会发生无法分配的问题,于是提前发生一次 Full GC。详细参考读懂一行Full GC日志(回复JVM内存分配担保机制一文中 Mr/Mrs Xxx 在留言区提出的问题)
注意:JDK 1.8 默认使用 UseParallelGC 垃圾回收器,该垃圾回收器默认启动了 AdaptiveSizePolicy,会根据 GC 的情况自动计算计算 Eden、From 和 To 区的大小

G1 Evacuation Pause

当没有更多的空闲 region 被提升到老一代或者复制到幸存空间时,并且由于堆已经达到最大值,堆不能扩展,从而发生 Evacuation Failure

G1 Humongous Allocation

Humongous(大型对象)是大于 G1 中 region 大小 50% 的对象。在大量分配之前,jvm 会检查它是否应该执行例行 Evacuation Pause 而不考虑实际分配大小,但如果由于此检查而触发,则将被列为大量分配。此情况也用于任何用于为分配释放足够空间的集合

Last ditch collection

对于 perm gen(java 7 或更早版本)和元空间(java 8+),如果分配失败并且无法扩展内存池时触发该 GC,表象为已经进行了一个 Metadata GC,然后又触发了 Last ditch collection
原因多为 metaspace 的内存碎片化,即引用过多且没有清除
举例:大量使用反射,在 Java 虚拟机中,每个类加载器都有一个 ClassLoaderData 的数据结构,ClassloaderData 内部有管理内存的 Metaspace,Metaspace 在 initialize 的时候会调用 get_initialization_chunk 分配第一块 Metachunk,类加载器在类的时候是以 Metablock 为单位来使用 Metachunk。当创建很多类加载器,而每个类加载器又加载了很少的类,即会出现该问题。详细参考:记一次诡异的频繁Full GC 大量类加载器创建导致诡异FullGC

ILLEGAL VALUE - last gc cause - ILLEGAL VALUE

Included for completeness,正常情况看不到此信息

unknown GCCause

与[转帖]GC 日志相似的内容:

[转帖]GC 日志

https://www.xjx100.cn/news/188814.html?action=onClick 垃圾回收器的发展历史 1999年:随JDK1.3.1一起来的串行方式Serial GC(第一款GC),ParNew GC是SerialGC的多线程版本。2002年:2月26日,Parallel

[转帖]GC日志分析工具——GCViewer案例

原创 石页粑粑 来自zxsk的码农 2020-09-28 06:18 一、GCViewer介绍 业界较为流行分析GC日志的两个工具——GCViewer、GCEasy。GCEasy部分功能还是要收费的,今天笔者给大家介绍一下GCViewer的使用与功能点。 二、GCViewer 使用 2.1 编译 首

【转帖】JAVA GC日志分析

https://zhuanlan.zhihu.com/p/613592552 ​ 目录 1. GC分类 针对HotSpot VM的实现,它里面的GC按照回收区域又分为两大种类型:一种是部分收集(Partial GC),一种是整堆收集(Full GC) 部分收集(Partial GC):不是完整收集整

【转帖】71.常用的显示GC日志的参数、GC日志分析、日志分析工具的使用

目录 1.常用的显示GC日志的参数2.图解垃圾`GC`日志(重要)3.日志分析工具的使用 1.常用的显示GC日志的参数 解释: 日志中,GC和Full GC表示的是GC的类型。GC只在新生代进行,Full GC包括新生代和老年代、方法区。 Allocation Failure:GC发生的原因,一般新

[转帖]GC overhead limit exceeded原因分析及解决方案

https://zhuanlan.zhihu.com/p/88956975 最近一个上线运行良好的项目出现用户无法登录或者执行某个操作时,有卡顿现象。查看了日志,出现了大量的java.lang.OutOfMemoryError: GC overhead limit exceeded错误。 oracl

[转帖]记一次使用gdb诊断gc问题全过程

https://www.cnblogs.com/codelogs/p/17092141.html 简介# 上次解决了GC长耗时问题后,系统果然平稳了许多,这是之前的文章《GC耗时高,原因竟是服务流量小?》然而,过了一段时间,我检查GC日志时,又发现了一个GC问题,如下:从这个图中可以发现,我们GC有

[转帖] 记一次使用gdb诊断gc问题全过程

记一次使用gdb诊断gc问题全过程 原创:扣钉日记(微信公众号ID:codelogs),欢迎分享,转载请保留出处。 简介# 上次解决了GC长耗时问题后,系统果然平稳了许多,这是之前的文章《GC耗时高,原因竟是服务流量小?》然而,过了一段时间,我检查GC日志时,又发现了一个GC问题,如下:从这个图中可

[转帖]【JVM】常用虚拟机参数及实例

常用参数表 参数描述-XX:+PrintGC启动java虚拟机后,只要遇到gc,就打印日志-XX:+PrintGCDetailsgc发生时,打印更详细的日志-XX:+PrintHeapAtGC每一次GC后,都打印堆信息-XX:+PrintGCTimeStampsgc发生时,额外打印gc时间,该时间为

[转帖]Code Cache满导致应用性能降低

https://juejin.cn/post/6844903601786060808 0 问题描述 一个应用在运行一段时间后,随着访问量不断增加,突然处理能力下降。但是从流量,jstack,gc上看基本正常。感觉好像突然从 “健康状态” 进入了 “虚弱状态”。 1 排查问题 在JVM日志里,可以发现

[转帖]Code Cache满导致应用性能降低

https://juejin.cn/post/6844903601786060808 0 问题描述 一个应用在运行一段时间后,随着访问量不断增加,突然处理能力下降。但是从流量,jstack,gc上看基本正常。感觉好像突然从 “健康状态” 进入了 “虚弱状态”。 1 排查问题 在JVM日志里,可以发现