JVM系列(四十四) JVM调优实战-EasyGC GC日志分析

贾子杰
1,100 阅读6分钟

EasyGC GC日志分析

前面我们其实讲了很多GC的日志分析，比如Eden区，Old区，但是有没有一种比较系统的方法呢？或者说有没有一种比较直观的方法可以根据日志去分析GC呢？

当然有，就是GCEasy， 今天我们来介绍一下如何根据gc日志来便捷直观的分析GC

1.什么是GCeasy

什么是gceasy？ gceasy是一个网站 ：gceasy.io/

用于在线分析gc日志，形成可视化的报表快速排查问题使用。

我们可以根据项目打印的gc日志 然后上传到gceasy网站, 点击Analyzing 分析 gc日志,就可以得到gc的报告分析, 我们可以直观的看出问题所在

  • 上传GC日志,点击 选择文件,选择本地的gc日志 xx.log
  • 分析GC日志, Analyze 就是gc日志分析

image.png

2.GC报告分析结果概览

首先看下第一项

  • Congratulations! Your application's GC activity is healthy 说明我们的gc没有严重的问题
  • Duration: 16 hrs 53 min 12 sec 本次GC日志统计时间时长 16小时 53分钟

image.png

3.JVM 内存大小分析

我们看下 JVM momory size ，这块根据gc日志，展示了年轻代YongGen，老年代Old Gen，元空间Meta space的分配大小信息及使用峰值信息， 通过这块 我们可以知道以下几点

Allocated 表示分配的空间大小， Peak表示峰值大小， 通过Peak峰值大小是否达到内存分配大小，我们可以决定 JVM内存是否要调整， -Xms、-Xmx、-Xmn，如果峰值远远小于分配大小， 这时候就可以适当减小内存设置

  • 比如我们的这个 YongGeneration 分配627，峰值614，几乎打满，可以适当提高年轻代大小
  • 老年代 Old Generation 分配 975， Peak 532， 才一半的使用率，可以适当减小老年代大小
  • Young + old + meta 一共分配4.5G， 峰值960， 可以适当减小内存信息

image.png

4.Key Performance Indicators 关键指标信息

关键指标信息 我们有以下四个指标

  • Throughput 99.944% 表示系统吞吐量， 表示系统花在非GC的时间占比，越高越好，说明用在业务上的越多
  • Avg Pause GC Time 平均GC消耗时间， 越小越好，建议50ms以下
  • Max Pause GC Time 最大单次GC消耗时间 越小越好，停顿时间长会影响使用
  • Time Range Duration 0-100， 1687， 99.59% 表示GC时间在0-100ms内的GC，发生了1687次， 占到GC总量的 99.559%
  • Time Range Duration 100-200， 7， 0.41% 表示GC时间在100-200ms内的GC，发生了7次， 占到GC总量的 0.41%

image.png

5.交互图表信息-我们比较关注的

Heap before GC GC前内存堆空间信息

  • 最高的点在 10：51发生， 那时刻YoungGC 堆大小980M image.png

Heap after GC GC发生后内存堆空间信息

  • GC发生后，此刻堆空间大小 575M image.png

gc Duration GC持续时间

  • 最长的耗时 还是在10：51 时刻，耗时达到了559ms

image.png

Pause GC Duration GC暂停时间

  • 可以查看YoungGC和FullGC的暂停时间， 我们业务没发生FullGC，可以看出YongGC暂停时间最长的分布大致还是上午 10：51 image.png

Reclaimed Bytes GC回收清理掉的垃圾信息

  • 真实GC清理掉垃圾情况，比较前几个参数，10：51 gc前 980M， 会收回 500M左右， 本次清理掉 Reclaimed Bytes 618M 空间 image.png

YoungGen 新生代使用情况

  • Allocated space 表示年轻代分配空间 458M
  • BeforeGC gc前使用了 457M
  • afterGC gc后使用空间8M
  • 可以计算出来 大概清理年轻代空间 457-8=449M, 对年轻代的清理还是比较彻底的 image.png

Old Gen 老年代使用情况

  • Allocated space 表示老年代分配空间 612M
  • BeforeGC gc前使用了 396M
  • afterGC gc后使用空间394M
  • 几乎没有清理掉垃圾， 说明老年代的对象都是一直使用的，几乎没有垃圾信息，本次gc才清理了 396-394=5M空间 image.png

A & P Allocation & Promotion 内存分配及晋升情况

  • Allocated objects size 表示堆内存的分配情况 447M
  • Promoted Young->Old objects size 表示从内存对象从 Young晋升为old的大小 5M image.png

5.G1 Collection Phases Statistics G1收集器统计信息

GC 统计信息，分别记录了每次G1垃圾收集器的统计信息

  • Count 每次GC过程 Younggc次数， 全局表示 ConcurrentMark次数，Remark重新标记次数 mixedGC 次数， initial-mark 全局初始化次数， CleadUp 标记清理次数，Total 一共GC次数
  • Avg GC time 上面的GC 过程的平均耗时信息
  • Min/Max Time 上面的GC 过程的 最小/最大 耗时信息
  • Avg Interval Time 平均每个 GC过程的间隔时间 image.png

6.G1 GC Time G1 GC时间

G1 垃圾收集器的GC时间， 统计了以下时间信息

  • Pause Time GC暂停的时间 比如GC过程Stop The World STW耗时
  • Concurrent Time 并发时间，比如GC过程中GC回收线程和用户线程并行的时间信息 image.png

7.Memory Leak & GC Causes 内存泄漏信息及GC原因

由于根据日志记录的应用程序，没有发生内存泄漏，所以Memork Leak 就没有内存泄漏的日志分析信息

GC Causes 记录了GC产生的原因

  • G1 Evacuation Pause G1垃圾收集，发生Count 1662次，AvgTime 平均耗时，MaxTime最大耗时， TotalTime总计耗时
  • G1 Humongous Allocation 大对象分配造成GC， 6次及耗时信息
  • Metadata GC Threshold 元空间大小限制 造成的GC, 2次及耗时信息 image.png

8.Object Stats & CPU Stats 对象信息及CPU信息

记录对象的创建，晋升，创建速度等信息及CPU 系统时间用户时间信息

  • Total created bytes 一共创建了多少对象信息 655G
  • Total promoted bytes 一共晋升了多少对象信息 805M
  • Avg creation rate 平均创建对象的速度 11M/s
  • Avg promotion rate 平均晋升的速度 13Kb/s
  • CPU 系统时间SysTime， 用户时间UserTime
  • 说明系统频繁的创建，销毁独象，但是 晋升老年代的对象非常非常少 image.png

JVM 参数信息 image.png

至此，我们已经能够通过EasyGC 可以直观的观察GC的情况，根据GC日志可以分析GC情况，有利于我们在项目中方便快捷的发现问题，解决GC问题

avatar
文章
阅读
粉丝