求你了,GC 日志打印别再瞎配置了

先点赞再看,养成好习惯

生产环境上,或者其他要测试 GC 问题的环境上,一定会配置上打印GC日志的参数,便于分析 GC 相关的问题。

但是可能很多人配置的都不够“完美”,要么是打印的内容过少,要么是输出到控制台,要么是一个大文件被覆盖,要么是……

本文带你一步一步,配置一个完美的 GC 日志打印策略

打印内容

为了保留足够多的“现场证据”,最好是把 GC 相关的信息打印的足够完整而且你的程序真的不差你GC时打印日志I/O消耗的那点性能

打印基本 GC 信息

打印 GC 日志的第一步,就是开启 GC 打印的参数了,也是最基本的参数。

-XX:+PrintGCDetails -XX:+PrintGCDateStamps

打印对象分布

为了分析 GC 时的晋升情况和晋升导致的高暂停,不看对象年龄分布日志怎么行

-XX:+PrintTenuringDistribution

输出内容示例:

Desired survivor size 59244544 bytes, new threshold 15 (max 15)
- age   1:     963176 bytes,     963176 total
- age   2:     791264 bytes,    1754440 total
- age   3:     210960 bytes,    1965400 total
- age   4:     167672 bytes,    2133072 total
- age   5:     172496 bytes,    2305568 total
- age   6:     107960 bytes,    2413528 total
- age   7:     205440 bytes,    2618968 total
- age   8:     185144 bytes,    2804112 total
- age   9:     195240 bytes,    2999352 total
- age  10:     169080 bytes,    3168432 total
- age  11:     114664 bytes,    3283096 total
- age  12:     168880 bytes,    3451976 total
- age  13:     167272 bytes,    3619248 total
- age  14:     387808 bytes,    4007056 total
- age  15:     168992 bytes,    4176048 total

GC 后打印堆数据

每次发生 GC 时,对比一下 GC 前后的堆内存情况,更直观

-XX:+PrintHeapAtGC

输出内容示例:

{Heap before GC invocations=0 (full 0):
 garbage-first heap   total 1024000K, used 324609K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 6 young (6144K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
Heap after GC invocations=1 (full 1):
 garbage-first heap   total 1024000K, used 21755K [0x0000000781800000, 0x0000000781901f40, 0x00000007c0000000)
  region size 1024K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 3420K, capacity 4500K, committed 4864K, reserved 1056768K
  class space    used 371K, capacity 388K, committed 512K, reserved 1048576K
}

打印 STW 时间

暂停时间是 GC 最重要的指标,肯定不能少

-XX:+PrintGCApplicationStoppedTime

输出内容示例:

Total time for which application threads were stopped: 0.0254260 seconds, Stopping threads took: 0.0000218 seconds

打印 safepoint 信息

进入STW阶段之前,需要要找到一个合适的 safepoint ,这个指标一样很重要(非必选,出现 GC 问题时最好加上此参数调试)

-XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

输出内容示例:

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.371: ParallelGCFailedAllocation       [      10          0              0    ]      [     0     0     0     0     7    ]  0   
Execute full gc...dataList has been promoted to cms old space
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.379: ParallelGCSystemGC               [      10          0              0    ]      [     0     0     0     0    16    ]  0   
         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.396: no vm operation                  [       9          1              1    ]      [     0     0     0     0   341    ]  0   

打印 Reference 处理信息

强引用/弱引用/软引用/虚引用/finalize 方法万一有问题,不得打印出来看看?

-XX:+PrintReferenceGC

输出内容示例:

2021-02-19T12:41:30.462+0800: 5072726.605: [SoftReference, 0 refs, 0.0000521 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [WeakReference, 0 refs, 0.0000069 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [FinalReference, 0 refs, 0.0000056 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [PhantomReference, 0 refs, 0 refs, 0.0000059 secs]
2021-02-19T12:41:30.462+0800: 5072726.605: [JNI Weak Reference, 0.0000131 secs], 0.4635293 secs]

完整参数

# requireds
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# optional
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

输出方式

上面只是定义了打印的内容,默认情况下,这些日志会输出到控制台(标准输出)。那如果你的程序日志也输出到控制台呢,这个日志内容就会很乱,分析起来很麻烦。如果你是追加的方式(比如 tomcat 的 catalina.out 就是追加),这个文件会越来越大,分析起来就要命了。

所以需要一种分割日志的机制,这个机制嘛……JVM自然是提供的。

JVM 的日志分割

JVM提供了几个用于分割 GC 日志的参数:

# GC日志输出的文件路径
-Xloggc:/path/to/gc.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件,超过之后从头开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小,超过就触发分割
-XX:GCLogFileSize=100M

按照这个参数,每个GC日志只要超过20M就会进行分割,最多分割5个文件,文件名依次是gc.log.0,gc.log.1,gc.log.2,gc.log.3,gc.log.4, .....

看似很美好,几行配置就搞定了输出文件的问题。但是这种方式有一些问题:

  1. -Xloggc 方式指定的日志文件,是覆盖写的方式,每次启动都会覆盖,历史日志会丢失
  2. 当超过最大分割数后,会从第0个文件开始重新写入,而且是覆盖
  3. -XX:NumberOfGCLogFiles 并不能设置为无限

这个覆盖的问题就有点恶心了,每次启动覆盖之前的历史日志……这谁能忍?

使用时间戳命名文件

于是有另一种解决方案。不使用 JVM 提供的日志分割功能,而是每次启动用时间戳命名日志文件,这样可以每次启动都使用不同的文件,就不会出现覆盖的问题了。

# 使用-%t作为日志文件名
-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc-%t.log

# 生成的文件名是这种:gc-2021-03-29_20-41-47.log

可是这样就完美吗?

虽然没有覆盖的问题,但由于没有日志分割的功能,每次启动后只有一个GC日志文件,单个日志文件可能会非常巨大。过大的日志文件分析起来是很麻烦的,必须得分割。

二者结合

这里只需要稍微调整一下策略,将 JVM 分割和时间戳命名两种方案结合,就可以得到最优的方式了。

# GC日志输出的文件路径
-Xloggc:/path/to/gc-%t.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件,超过之后从头开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小,超过就触发分割
-XX:GCLogFileSize=100M

配置时间戳作文 GC 日志文件名的同时,也配置JVM的GC日志分割策略。这样一来,既保证了 GC 文件不会被覆盖,又保证了单个 GC 文件的大小不会过大,完美!

最终得到的日志文件名会像这个样子:

  1. gc-2021-03-29_20-41-47.log.0
  2. gc-2021-03-29_20-41-47.log.1
  3. gc-2021-03-29_20-41-47.log.2
  4. gc-2021-03-29_20-41-47.log.3
  5. ....

最佳实践 - 完整参数

# 必备
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps 
-XX:+PrintTenuringDistribution 
-XX:+PrintHeapAtGC 
-XX:+PrintReferenceGC 
-XX:+PrintGCApplicationStoppedTime

# 可选
-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount=1

# GC日志输出的文件路径
-Xloggc:/path/to/gc-%t.log
# 开启日志文件分割
-XX:+UseGCLogFileRotation 
# 最多分割几个文件,超过之后从头文件开始写
-XX:NumberOfGCLogFiles=14
# 每个文件上限大小,超过就触发分割
-XX:GCLogFileSize=100M

原创不易,禁止未授权的转载。如果我的文章对您有帮助,就请点赞/收藏/关注鼓励支持一下吧❤❤❤❤❤❤

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

推荐阅读更多精彩内容