jvm性能调优-分析GC日志

GC日志可视化分析工具

GCeasy   https://www.gceasy.io/

JDK8 GC日志打印相关参数

另外开启如下参数,可打印GC相关的更多信息,帮助我们更好的分析G1日志 

示例:
java -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+UseSerialGC -Xmx50m -Xloggc:/Users/itmuch.com/gc.log xxx.jar
Young GC日志:
2020-05-08T11:11:52.823-0800: 0.705: [GC (Allocation Failure) 2020-05-08T11:11:52.823-0800: 0.705: [DefNew: 15289K->1343K(15360K), 0.0036231 secs] 18555K->5065K(49536K), 0.0037065 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

其中:

2020-05-08T11:11:52.823-0800:当前时间戳,由PrintGCDateStamps控制
0.705:当前相对时间戳,表示应用启动多久后触发,由PrintGCTimeStamps控制
GC (Allocation Failure):造成GC的原因,由PrintGCCause控制
[DefNew: 15289K->1343K(15360K), 0.0036231 secs]:

        DefNew:使用不同垃圾收集器,这里的展示不同:

                使用Serial收集器:显示DefNew,表示Default New
                使用ParNew收集器:显示ParNew
                使用Paralle Scavenge收集器:显示PSYoungGen
                使用G1:G1格式和这个日志格式不一样,很好区分
        15289K:回收前,年轻代使用的大小
        1343K:回收后,年轻代使用的大小
        15360K:年轻代总大小
        0.0036231:花费了多久
18555K:回收前,堆使用的大小
5065K:回收后,堆使用的大小
49536K:堆的总大小
0.0037065 secs:花费时间
user=0.00:用户耗时
sys=0.00:系统耗时
real=0.00:实际耗时 

Full GC日志:
2020-05-08T11:28:16.911-0800: 7.863: [Full GC (Allocation Failure) 2020-05-08T11:28:16.911-0800: 7.863: [Tenured: 6847K->6848K(6848K), 0.0329351 secs] 9914K->9483K(9920K), [Metaspace: 30156K->30156K(1077248K)], 0.0330357 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 

其中:

2020-05-08T11:28:16.911-0800:当前时间戳,由PrintGCDateStamps控制
7.863:当前相对时间戳,表示应用启动多久后触发,由PrintGCTimeStamps控制
Full GC (Allocation Failure) :造成GC的原因,由PrintGCCause控制
[Tenured: 6847K->6848K(6848K), 0.0329351 secs]

        Tenured:使用不同垃圾收集器,这里的展示不同:

                使用Serial Old收集器:显示Tenured
                使用Parallel Old收集器:显示ParOldGen
                使用CMS收集器:显示CMS
        6847K:回收前,老年代使用的大小
        6848K:回收后,老年代使用的大小
        6848K:老年代总大小
        0.0329351:花费时间
9914K:回收前,堆使用的大小
9483K:回收后,堆使用的大小
9920K:堆的总大小
[Metaspace: 30156K->30156K(1077248K)], 0.0330357 secs]:元空间的使用情况
[Times: user=0.03 sys=0.00, real=0.03 secs] :同新生代日志

G1日志:

如使用的是G1垃圾收集器,那么在上面表格的基础上,还有如下参数:

Young GC日志:

示例:

2020-05-08T14:19:58.598-0800: 5.599: [GC pause (G1 Evacuation Pause) (young), 0.0035900 secs]
   [Parallel Time: 2.4 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 5598.7, Avg: 5599.1, Max: 5600.8, Diff: 2.1]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.4]
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.8, Diff: 1.8, Sum: 6.4]
         [Processed Buffers: Min: 0, Avg: 2.2, Max: 6, Diff: 6, Sum: 18]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7]
         [Termination Attempts: Min: 1, Avg: 2.4, Max: 12, Diff: 11, Sum: 19]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.9, Diff: 0.9, Sum: 0.9]
      [GC Worker Total (ms): Min: 0.2, Avg: 1.9, Max: 2.3, Diff: 2.2, Sum: 15.3]
      [GC Worker End (ms): Min: 5601.0, Avg: 5601.0, Max: 5601.0, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 1.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 24.3M(30.0M)->20.6M(30.0M)]
 [Times: user=0.01 sys=0.00, real=0.01 secs] 

 解读:

# 这是一个年轻代GC,花费了0.0018345。下面的缩进,表示这行日志的子任务
2020-05-08T14:19:58.598-0800: 5.599: [GC pause (G1 Evacuation Pause) (young), 0.0035900 secs]
   # 并行任务,并行GC花费2.4毫秒,并行阶段有8个线程
   [Parallel Time: 2.4 ms, GC Workers: 8]
      # 表示各个GC工作线程在应用启动多久(毫秒)后启动。
      # 同时还做了个统计,例如这些GC线程最早启动的那个线程在应用启动后847.9毫秒后启动等
      [GC Worker Start (ms): Min: 5598.7, Avg: 5599.1, Max: 5600.8, Diff: 2.1]
      # 表示各个GC工作线程扫描跟对象花费的时间的统计
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.7, Sum: 2.4]
      # 表示各个GC工作线程更新Remembered Sets花费的时间的统计
      # Remembered Sets是保存到堆中的区域的跟踪引用。设值方法线程持续改变对象图,自此引指向一个特定的区域。我们保存这些改变的跟踪信息到叫作Update Buffers的更新缓存中。Update RS子任务不能并发的处理更新缓存,更新一致所有区域的Remembered Sets
      [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 1.8, Diff: 1.8, Sum: 6.4]
         # 表示每个GC工作线程处理的Update Buffers的数量统计
         [Processed Buffers: Min: 0, Avg: 2.2, Max: 6, Diff: 6, Sum: 18]
      # 每个GC工作线程扫描Remembered Sets花费的时间
      # 一个区域的Remembered Sets包含指向这个区域的引用的相符合的卡片。这个阶段扫描这些卡片寻找指向所有这些区域的Collection Set的引用
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # 扫描Code Root耗时统计。Code Root是JIT编译后的代码里引用了heap中的对象
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      # 拷贝存活对象到新的Region耗时统计
      [Object Copy (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7]
      # 各个GC工作线程完成任务后尝试中断GC线程到真正中断的耗时统计
      # 在某个GC线程中断之前,会检查其它线程的工作队列,如果发现依然有任务,会帮助处理,之后再中断
      [Termination (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7]
         # 尝试中断次数统计
         [Termination Attempts: Min: 1, Avg: 2.4, Max: 12, Diff: 11, Sum: 19]
      # GC工作线程花费在其他工作上的时间统计
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.9, Diff: 0.9, Sum: 0.9]
      # 各个GC工作线程花费的时间总和统计
      [GC Worker Total (ms): Min: 0.2, Avg: 1.9, Max: 2.3, Diff: 2.2, Sum: 15.3]
      # 各个GC工作线程线程的结束时间,min|max分别表示第一个|最后一个线程的结束时间。
      [GC Worker End (ms): Min: 5601.0, Avg: 5601.0, Max: 5601.0, Diff: 0.0]
   # 串行任务,修复GC期间code root指针改变的耗时
   [Code Root Fixup: 0.0 ms]
   # 串行任务,清除Code Root耗时
   [Code Root Purge: 0.0 ms]
   # 清除Card Table中的Dirty Card的耗时
   [Clear CT: 0.1 ms]
   # 其他任务
   [Other: 1.1 ms]
      # 为Collection Set选择区域所花费的时间
      [Choose CSet: 0.0 ms]
      # 花费在处理引用对象上的时间
      [Ref Proc: 0.7 ms]
      # 引用入队到ReferenceQueues花费的时间,可用-XX:+ParallelRefProcEnabled,并行处理这一步
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.3 ms]
      # 处理超大对象
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      # 释放Collection Set数据结构花费的时间
      [Free CSet: 0.0 ms]
   # 各个区域的内存变化。
   # 4096.0K:伊甸园当前占用4096.0K
   # (4096.0K):伊甸园总大小4096.0K
   # 0.0B:收集后,伊甸园占用将会变成0
   # (4096.0K):伊甸园的目标大小(如有需要,JVM可能会自动增加伊甸园大小)
   [Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 1024.0K->1024.0K Heap: 24.3M(30.0M)->20.6M(30.0M)]
 # 用户耗时、系统耗时、实际耗时
 [Times: user=0.01 sys=0.00, real=0.01 secs] 

并发回收日志:

# 1. 初始标记(stop the world)
2020-05-08T14:19:54.076-0800: 1.076: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0107606 secs]
   [Parallel Time: 8.2 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1076.6, Avg: 1077.1, Max: 1077.5, Diff: 0.9]
      [Ext Root Scanning (ms): Min: 0.1, Avg: 2.9, Max: 4.6, Diff: 4.5, Sum: 23.2]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 1.4, Diff: 1.4, Sum: 3.4]
         [Processed Buffers: Min: 0, Avg: 1.8, Max: 7, Diff: 7, Sum: 14]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
      [Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 1.5, Diff: 1.5, Sum: 4.2]
      [Termination (ms): Min: 0.0, Avg: 2.6, Max: 4.3, Diff: 4.3, Sum: 20.9]
         [Termination Attempts: Min: 1, Avg: 2.4, Max: 6, Diff: 5, Sum: 19]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 4.4, Avg: 6.5, Max: 8.0, Diff: 3.6, Sum: 51.9]
      [GC Worker End (ms): Min: 1082.0, Avg: 1083.6, Max: 1084.7, Diff: 2.7]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 2.2 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 1024.0K(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 15.3M(30.0M)->14.4M(30.0M)]
 [Times: user=0.01 sys=0.00, real=0.01 secs] 
# 开始扫描初始标记阶段Survivor区的Root Region
2020-05-08T14:19:54.087-0800: 1.087: [GC concurrent-root-region-scan-start]
# 扫描完成
2020-05-08T14:19:54.091-0800: 1.092: [GC concurrent-root-region-scan-end, 0.0049225 secs]
# 2. 并发标记,标记线程数可用-XX:ConcGCThreads指定
2020-05-08T14:19:54.092-0800: 1.092: [GC concurrent-mark-start]
# 并发标记结束
2020-05-08T14:19:54.102-0800: 1.103: [GC concurrent-mark-end, 0.0106528 secs]
# 3. 最终标记(stop the world)
2020-05-08T14:19:54.103-0800: 1.104: [GC remark 2020-05-08T14:19:54.103-0800: 1.104: [Finalize Marking, 0.0028699 secs] 2020-05-08T14:19:54.106-0800: 1.107: [GC ref-proc, 0.0001689 secs] 2020-05-08T14:19:54.106-0800: 1.107: [Unloading, 0.0053988 secs], 0.0087250 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs] 
# 4. 筛选回收(stop the world)
# 没有存活对象的Old Region和Humongous Region将被释放和清空。
# 为了准备下次GC,在CSets中的Old Regions会根据他们的回收收益的大小排序。
2020-05-08T14:19:54.114-0800: 1.114: [GC cleanup 15M->14M(30M), 0.0006027 secs]
 [Times: user=0.00 sys=0.00, real=0.00 secs] 
# 并发清理开始
2020-05-08T14:19:54.114-0800: 1.115: [GC concurrent-cleanup-start]
# 并发清理结束
2020-05-08T14:19:54.114-0800: 1.115: [GC concurrent-cleanup-end, 0.0000133 secs]

  • 0
    点赞
  • 1
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值