[每日一氵] PySpark 的 log GC 部分是什么意思

2024-11-15T11:10:40.292+0800: 2850.503: [GC (Allocation Failure) [PSYoungGen: 142705K->3472K(141312K)] 1403514K->1264289K(1543168K), 0.0170225 secs] [Times: user=0.05 sys=0.00, real=0.01 secs] 

这一行日志来自Java的垃圾收集器（Garbage Collector, GC），并且是在使用Spark时产生的。下面会逐一解释这一行日志中的各个部分：

1. 时间戳：2024-11-15T11:10:40.292+0800 这表示垃圾收集事件发生在2024年11月15日，时间是11:10:40.292，时区是+0800（即东八区，通常是中国、台湾、香港、澳门等地的时区）。
2. GC事件：2850.503: [GC (Allocation Failure)2850.503：这是Java虚拟机（JVM）启动后的秒数，表示从JVM启动到这次GC事件发生已经过去了大约2850.503秒。[GC (Allocation Failure)：这表示发生了一次GC事件，原因是“分配失败”（Allocation Failure），即JVM在尝试为新对象分配内存时，发现没有足够的空间，从而触发了垃圾收集。内存变化：[PSYoungGen: 142705K->3472K(141312K)] 1403514K->1264289K(1543168K)PSYoungGen: 这是指“Parallel Scavenge Young Generation”，是Java堆内存中的年轻代部分。年轻代通常包含新创建的对象。142705K->3472K(141312K): 这表示在GC之前，年轻代使用了142705K的内存，GC之后减少到了3472K。年轻代的总容量是141312K。1403514K->1264289K(1543168K): 这表示整个Java堆在GC之前使用了1403514K的内存，GC之后减少到了1264289K。整个堆的总容量是1543168K。耗时：0.0170225 secs
3. 这表示这次GC事件总共耗费了 0.0170225 秒。 时间细节：[Times: user=0.05 sys=0.00, real=0.01 secs]user=0.05: 这表示在用户模式下（即执行Java代码时）耗费了0.05秒。sys=0.00: 这表示在系统模式下（即执行操作系统代码，如垃圾收集器本身）耗费了0.00秒。real=0.01: 这表示从GC事件开始到结束实际经过的时间是0.01秒，这通常包括了等待时间和其他非计算开销。

2024-11-15T10:59:09.768+0800: 2159.978: [Full GC (Ergonomics) [PSYoungGen: 1952K->0K(123904K)] [ParOldGen: 1196156K->1165762K(1401856K)] 1198108K->1165762K(1525760K), [Metaspace: 161537K->161537K(1202176K)], 2.0533133 secs] 
[Times: user=7.57 sys=0.01, real=2.05 secs]

• 时间戳: 2024-11-15T10:59:09.768+0800，发生在2024年11月15日 10:59:09。
• GC类型: Full GC，表示发生了全局垃圾收集，这通常涉及到整个堆的清理。
• 触发原因: (Ergonomics)，表明垃圾收集是基于JVM的自动调整策略触发的。
• 内存变化:- PSYoungGen: 年轻代从1952K清理到0K。- ParOldGen: 老年代从1196156K减少到1165762K。- 总堆内存: 从1198108K减少到1165762K。- Metaspace: 元空间大小未变，保持在161537K。- 耗时: 2.0533133 secs，表明Full GC花费了大约2.05秒。
• 时间细节: 用户模式7.57秒，系统模式0.01秒，实际耗时2.05秒。这里的用户模式时间远大于实际耗时，可能是因为GC过程中多个线程并行工作。

2024-11-15T10:54:06.273+0800: 1856.484: [Full GC (System.gc()) [PSYoungGen: 2368K->0K(389632K)] [ParOldGen: 1052564K->1035143K(1197056K)] 1054932K->1035143K(1586688K), [Metaspace: 161469K->161469K(1202176K)], 2.7494377 secs] [Times: user=9.01 sys=0.03, real=2.75 secs]

• 时间戳: 2024-11-15T10:54:06.273+0800，发生在2024年11月15日 10:54:06。
• GC类型: Full GC，同样是全局垃圾收集。
• 触发原因: (System.gc())，表明垃圾收集是由System.gc()调用触发的，这通常是由应用程序或开发者显式调用的。
• 内存变化: - PSYoungGen: 年轻代从2368K清理到0K。- ParOldGen: 老年代从1052564K减少到1035143K。- 总堆内存: 从1054932K减少到1035143K。- Metaspace: 元空间大小未变，保持在161469K。- 耗时: 2.7494377 secs，Full GC花费了大约2.75秒。
• 时间细节: 用户模式9.01秒，系统模式0.03秒，实际耗时2.75秒。这里的用户模式时间也远大于实际耗时。

2024-11-15T10:24:30.644+0800: 80.855: [GC (Metadata GC Threshold) [PSYoungGen: 87878K->7167K(194048K)] 115047K->44846K(422400K), 0.0238500 secs] [Times: user=0.08 sys=0.01, real=0.02 secs]

• 时间戳: 2024-11-15T10:24:30.644+0800，发生在2024年11月15日 10:24:30。
• GC类型: GC，这表明不是Full GC，可能是针对年轻代的垃圾收集。
• 触发原因: (Metadata GC Threshold)，表明垃圾收集是由于元空间使用达到了某个阈值而触发的。
• 内存变化: - PSYoungGen: 年轻代从87878K减少到7167K。- 总堆内存: 从115047K减少到44846K（这里没有明确给出老年代的变化）。- 耗时: 0.0238500 secs，这次GC事件非常快，仅耗时约0.02秒。
• 时间细节: 用户模式0.08秒，系统模式0.01秒，实际耗时0.02秒。这里的用户模式时间和实际耗时比较接近。