JVM 技术详解:GC 日志解读与分析(实例分析上篇)

在 JDK 9 之后的版本中,启动参数有一些变化,继续使用原来的参数配置可能会在启动时报错。不过也不用担心,如果碰到,一般都可以从错误提示中找到对应的处置措施和解决方案。

例如 JDK 11 版本中打印 info 级别 GC 日志的启动脚本:

# JDK 11 环境,输出 info 级别的 GC 日志
java -Xms512m -Xmx512m
-Xlog:gc*=info:file=gc.log:time:filecount=0
demo.jvm0204.GCLogAnalysis

从 JDK 9 开始,可以使用命令 java -Xlog:help 来查看当前 JVM 支持的日志参数,本文不进行详细的介绍,有兴趣的同学可以查看 JEP 158: Unified JVM LoggingJEP 271: Unified GC Logging

另外,JMX 技术提供了 GC 事件的通知机制,监听 GC 事件的示例程序我们会在《应对容器时代面临的挑战》这一章节中给出。

但很多情况下 JMX 通知事件中报告的 GC 数据并不完全,只是一个粗略的统计汇总。

GC 日志才是我们了解 JVM 和垃圾收集器最可靠和全面的信息,因为里面包含了很多细节。再次强调,分析 GC 日志是一项很有价值的技能,能帮助我们更好地排查性能问题。

下面我们通过实际操作来分析和解读 GC 日志。

Serial GC 日志解读

关于串行垃圾收集器的介绍,请参考前面的文章:《常见 GC 算法介绍》。

首先,为了打开 GC 日志记录,我们使用下面的 JVM 启动参数如下:

# 请注意命令行启动时没有换行,此处是手工排版
java -XX:+UseSerialGC
-Xms512m -Xmx512m
-Xloggc:gc.demo.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
demo.jvm0204.GCLogAnalysis

让我们看看 Serial GC 的垃圾收集日志,并从中提取信息。

启用串行垃圾收集器,程序执行后输出的 GC 日志类似这样(为了方便大家阅读,已手工折行):

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) ......
Memory: 4k page,physical 16777216k(1551624k free)
CommandLine flags:
  -XX:InitialHeapSize=536870912 -XX:MaxHeapSize=536870912
  -XX:+PrintGC -XX:+PrintGCDateStamps
  -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
  -XX:+UseCompressedClassPointers -XX:+UseCompressedOops
  -XX:+UseSerialGC
2019-12-15T15:18:36.592-0800: 0.420:
  [GC (Allocation Failure)
    2019-12-15T15:18:36.592-0800: 0.420:
    [DefNew: 139776K->17472K(157248K),0.0364555 secs]
    139776K->47032K(506816K),
    0.0365665 secs]
  [Times: user=0.02 sys=0.01,real=0.03 secs]
......
2019-12-15T15:18:37.081-0800: 0.908:
  [GC (Allocation Failure)
    2019-12-15T15:18:37.081-0800: 0.908:
    [DefNew: 156152K->156152K(157248K),0.0000331 secs]
    2019-12-15T15:18:37.081-0800: 0.908:
    [Tenured: 299394K->225431K(349568K),0.0539242 secs]
    455546K->225431K(506816K),
    [Metaspace: 3431K->3431K(1056768K)],
    0.0540948 secs]
  [Times: user=0.05 sys=0.00,real=0.05 secs]

日志的第一行是 JVM 版本信息,第二行往后到第一个时间戳之间的部分,展示了内存分页、物理内存大小,命令行参数等信息,这部分前面介绍过,不在累述。

仔细观察,我们发现在这段日志中发生了两次 GC 事件,其中一次清理的是年轻代,另一次清理的是整个堆内存。让我们先来分析前一次年轻代 GC 事件。

Minor GC 日志分析

这次年轻代 GC 事件对应的日志内容:

2019-12-15T15:18:36.592-0800: 0.420:
  [GC (Allocation Failure)
    2019-12-15T15:18:36.592-0800: 0.420:
    [DefNew: 139776K->17472K(157248K),0.0364555 secs]
    139776K->47032K(506816K),
    0.0365665 secs]
  [Times: user=0.02 sys=0.01,real=0.03 secs]

从中可以解读出这些信息:

还有 93% 的精彩内容
最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
支付 ¥19.99 继续阅读
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 217,542评论 6 504
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,822评论 3 394
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 163,912评论 0 354
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,449评论 1 293
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,500评论 6 392
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,370评论 1 302
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,193评论 3 418
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 39,074评论 0 276
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,505评论 1 314
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,722评论 3 335
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,841评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,569评论 5 345
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 41,168评论 3 328
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,783评论 0 22
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,918评论 1 269
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,962评论 2 370
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,781评论 2 354