Spark GC日志分析

学习内容：

• 了解 Java VisualVM
• 分析gc日志

---

Java VisualVM：

工具在目录：C:\Java\jdk1.8.0_181\bin**

功能介绍

• 1.抽样器，点击内存，就可以看到各个类占用内存大小，实例数量，一眼就能定位到具体的异常方法。

• 2.点击监视 可以看到堆内存的使用情况
  
• 3.插件下载
  
• 4.点击下载Visual GC插件。可以看到各代内存情况
  
• 5.远程jvm，可以监控服务器上的应用
  
• 6.分析dump文件
  

我们可以使用Java VisualVM浏览堆heap dump文件的内容，并查看堆中已分配的对象。 对我们需要进行heap dump分析的java程序点右键就能找到heap dump选项。一次heap dump是特定时间点Java虚拟机（JVM）堆中所有对象的一个快照。 JVM为所有类实例和数组对象在堆中分配内存。 当不再需要对象且没有对象的引用时，垃圾收集器将回收堆内存。 通过检查堆，可以找到创建对象的位置，并查找对这些对象的引用。 如果JVM无法从堆中删除不需要的对象，Java VisualVM可以帮助我们找到对象的最近的GC Root

• 6.1 class ，类的列表以及该类引用的实例的数量和百分比。 通过右键单击名称并选择查看nstances，可以查看特定类的实例列表。
  

可以发现占据最大堆内存的是一个byte类型的数组。另外有句题外话，在上图中我们发现String和char[]这两个类的数量几乎是相当的，这从侧面印证了String内部是由Char数组实现的。

---

GC日志分析：

本次GC日志是线上的Spark程序生成的。
spark 打印GC日志参数：

--conf "spark.executor.extraJavaOptions= -verbose:gc -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC" 

--conf "spark.driver.extraJavaOptions= -verbose:gc -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC"

分析：

33.125：[GC[DefNew: 3324k->152k(3712k), 0.0025925 secs] 3324k>152k(11904k),0.0031680 secs]

从左至右，各个信息的意思为：

• 33.125： 自虚拟机启动以来经过的秒数，单位为秒；
• GC： 垃圾收集的停顿类型为不需要STW（Stop The World ）。如果是Full GC说明发生了STW。
  如果是Full GC (System)说明是调用System.gc()方法所触发的收集。
• DefNew：表示GC发生的区域在新生代。这个名称和所使用的收集器密切相关。可以有Tenured、Perm、ParNew、PSYoungGen等等。其中hotspot虚拟机使用的是PSYoungGen代表新生代
• 3324k->152k(3712k)：GC前该区域（DefNew）已使用容量->GC后该区域已使用容量（该内存区域总容量）
• 0.0025925 secs：该内存区域（DefNew）GC所占用的时间。
• 3324k->152k(11904k)：GC前Java堆已使用容量->GC后Java堆已使用容量（Java堆总容量）

---

红色框：这个是参数 -XX:+PrintHeapAtGC的作用，可以直观的看到gc前后的堆内情况

//上图 蓝色部分
2022-07-26T18:59:58.040+0800: 23.716: [GC (Allocation Failure) [PSYoungGen: 527872K->24904K(613376K)] 561160K->58201K(2011648K), 0.0412419 secs] [Times: user=0.17 sys=0.02, real=0.04 secs] 

• 2022-07-26T18:59:58.040+0800: gc日志记录时间
• 23.716：gc发生时，虚拟机运行了多少秒
• GC (Allocation Failure)：发生了一次垃圾回收，若前面有Full则表明是Full GC，没有Full的修饰表明这是一次Minor GC 。注意它不表示只GC新生代
• Allocation Failure：gc发生的原因，这里的Allocation Failure的原因是年轻代中没有足够区域能够存放需要分配的数据而失败
• PSYoungGen:ParallelScavenge(PS):此垃圾回收器为多线程回收机制，适用于内存比较大的时候
• 527872K->24904K(613376K)：垃圾收集前后的年轻代内存使用情况，其中前面的527872K为gc之前的使用量，24904K为gc之后的内存使用量。括号里的613376K为该内存区域的总量
• 561160K->58201K(2011648K)：垃圾收集前后整个堆内存的使用情况，括号里的为整个可以的堆内存的容量。
• 0.0412419 secs ：gc持续时间
• [Times: user=0.17 sys=0.02, real=0.04 secs] ：分别表示用户态耗时，内核态耗时和总耗时。

---

2022-07-26T18:59:44.478+0800: 26.155: [GC (Metadata GC Threshold) [PSYoungGen: 240047K->20620K(548864K)] 273344K->53925K(1947136K), 0.0370581 secs] [Times: user=0.29 sys=0.02, real=0.04 secs] 

• 是一次minor gc

• gc原因是：Metadata GC Threshold。Metadata即元数据的意思。我们可以看出这是与虚拟机的元数据区有关系的一次gc。元数据区，在jdk1.8以前又叫永久代，从JDK8开始，永久代(PermGen)的概念被废弃掉了，取而代之的就是这里的称为Metaspace的存储空间。元空间和永久代是虚拟机对方法区这个概念的一个具体实现。对于元空间而言，这一块空间是存在本地内存当中的。

• 以前只认为，Metaspace区是保存在本地内存中，是没有上限的，经查阅资料才发现，原来JDK8中，XX:MaxMetaspaceSize确实是没有上限的，最大容量与机器的内存有关；但是XX:MetaspaceSize是有一个默认值的：21M
  一般情况下我们就设置一个XX:MetaspaceSize的JVM启动参数：-XX:MetaspaceSize=128M

• 这里元空间发生gc，说明元空间的内存不够了，到达了阀值。对元空间进行了一次垃圾回收，回收之前是240047K，回收之后是20620K

---

2022-07-26T18:59:44.391+0800: 10.068: [Full GC (Metadata GC Threshold) [PSYoungGen: 27258K->0K(613376K)] [ParOldGen: 18913K->33288K(1398272K)] 46172K->33288K(2011648K), [Metaspace: 55916K->55916K(1099776K)], 0.1719903 secs] [Times: user=2.97 sys=0.25, real=0.17 secs] 

• 在元空间gc之后，紧接着发生了一次Full GC，且触发原因也是元空间不足。

• [PSYoungGen: 27258K->0K(613376K)] ：年轻代进行了一次gc

• [ParOldGen: 18913K->33288K(1398272K)] ：老年代进行了一次gc

• [Metaspace: 55916K->55916K(1099776K)] ： 元空间（方法区）发生了一次gc，但是值得注意的是，gc前后内存使用情况并没有发生任何改变。同时，元空间总的可使用的内存为：1gb。

---

{
    Heap before GC invocations=4275 (full 84):
 PSYoungGen      total 673792K, used 648704K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 648704K, 100% used [0x00000000d5580000,0x00000000fcf00000,0x00000000fcf00000)
  from space 25088K, 0% used [0x00000000fcf00000,0x00000000fcf00000,0x00000000fe780000)
  to   space 25088K, 0% used [0x00000000fe780000,0x00000000fe780000,0x0000000100000000)
 ParOldGen       total 1398272K, used 1397936K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 99% used [0x0000000080000000,0x00000000d552c020,0x00000000d5580000)
 Metaspace       used 133520K, capacity 143098K, committed 143508K, reserved 1175552K
  class space    used 16519K, capacity 17415K, committed 17596K, reserved 1048576K

2022-07-27T00:06:39.271+0800: 18424.947: [Full GC (Ergonomics) [PSYoungGen: 648704K->38610K(673792K)] [ParOldGen: 1397936K->1397899K(1398272K)] 2046640K->1436509K(2072064K), [Metaspace: 133520K->133520K(1175552K)], 0.7624691 secs] [Times: user=17.74 sys=0.01, real=0.76 secs] 

Heap after GC invocations=4275 (full 84):
 PSYoungGen      total 673792K, used 38610K [0x00000000d5580000, 0x0000000100000000, 0x0000000100000000)
  eden space 648704K, 5% used [0x00000000d5580000,0x00000000d7b34870,0x00000000fcf00000)
  from space 25088K, 0% used [0x00000000fcf00000,0x00000000fcf00000,0x00000000fe780000)
  to   space 25088K, 0% used [0x00000000fe780000,0x00000000fe780000,0x0000000100000000)
 ParOldGen       total 1398272K, used 1397899K [0x0000000080000000, 0x00000000d5580000, 0x00000000d5580000)
  object space 1398272K, 99% used [0x0000000080000000,0x00000000d5522c38,0x00000000d5580000)
 Metaspace       used 133520K, capacity 143098K, committed 143508K, reserved 1175552K
  class space    used 16519K, capacity 17415K, committed 17596K, reserved 1048576K
}

• Full GC (Ergonomics)：原因Ergonomics
• [ParOldGen: 1397936K->1397899K(1398272K)]：此时gc已经对老年代起不到任何作用了。原因：
  1.gc本身没有回收多少对象
  2.gc回收了很多对象，但同时又有更多的对象进入老年代
• [Metaspace: 133520K->133520K(1175552K)]：元数据空间也没多大变化

---

以上是gc日志的分析，下几篇会讲解一下常见的full gc情况的排查和解决过程