本文探讨了Java垃圾收集器的工作原理、GC日志的重要性以及如何启用和分析GC日志。垃圾收集日志是理解JVM内存管理和性能优化的关键，通过日志可以了解垃圾收集器行为、资源使用情况以及潜在问题。文章介绍了如何在不同Java版本中启用GC日志，以及分析工具如GCViewer和GCEasy的使用，强调了健康GC过程对于应用程序性能的重要性。
使用Java或任何其他基于JVM的编程语言时，我们免费提供某些功能。 这些功能之一是清除内存。 如果您曾经使用过C / C ++之类的语言，那么您可能还记得malloc ， calloc ， realloc和free之类的函数 。 我们需要注意内存中每个字节的分配，并在不再需要时释放所分配的内存。 没有这些，我们很快就会陷入内存不足，从而导致不稳定和崩溃。
使用Java，我们不必担心释放分配给对象的内存。 我们只需要停止使用该对象。 就这么简单。 一旦不再从我们的代码内部引用该对象，则可以释放该内存并再次使用。
释放内存是由JVM中称为Garbage Collector的专门部分完成的。
Java垃圾收集器如何工作
Java虚拟机在后台运行垃圾收集器以查找未使用的引用。 此类引用所使用的内存可以释放并重新使用。 与C / C ++之类的语言相比，您已经可以看到差异。 您不必将对象标记为删除，就足以停止使用它。
堆内存也分为不同的区域，每个区域都有自己的垃圾收集器类型。 垃圾收集器有一些实现-只要满足规范，每个JVM都有自己的实现。 在理论和实践上，每个JVM供应商都可以提供自己的垃圾回收器实现，从而提供不同的性能。
JVM Heap的三个主要区域的简化视图可以如下所示：
拥有一个健康的垃圾回收过程对于实现基于JVM的应用程序的最佳性能至关重要。 因此，我们需要确保监视JVM及其垃圾收集器 。 通过使用日志，我们可以了解JVM告诉我们有关垃圾收集器工作的内容。
什么是垃圾收集（GC）日志
垃圾收集器日志是Java虚拟机生成的文本文件，描述了垃圾收集器的工作。 它包含查看内存清洁过程如何工作所需的所有信息。 它还显示了垃圾收集器的行为以及使用了多少资源。 尽管我们可以使用APM提供程序或内部构建的监视工具监视应用程序，但是垃圾收集器日志对于在堆内存利用率方面快速识别任何潜在问题和瓶颈将是无价的。
您可以在垃圾回收日志中找到的示例如下所示：
2019-10-29T10:00:28.693-0100: 0.302: [GC (Allocation Failure) 2019-10-29T10:00:28.693-0100: 0.302: [ParNew
Desired survivor size 1114112 bytes, new threshold 1 (max 6)
- age 1: 2184256 bytes, 2184256 total
: 17472K->2175K(19648K), 0.0011358 secs] 17472K->2382K(63360K), 0.0012071 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
2019-10-29T10:00:28.694-0100: 0.303: Total time for which application threads were stopped: 0.0012996 seconds, Stopping threads took: 0.0000088 seconds
2019-10-29T10:00:28.879-0100: 0.488: Total time for which application threads were stopped: 0.0001006 seconds, Stopping threads took: 0.0000065 seconds
2019-10-29T10:00:28.897-0100: 0.506: Total time for which application threads were stopped: 0.0000981 seconds, Stopping threads took: 0.0000076 seconds
2019-10-29T10:00:28.910-0100: 0.519: Total time for which application threads were stopped: 0.0000896 seconds, Stopping threads took: 0.0000062 seconds
2019-10-29T10:00:28.923-0100: 0.531: Total time for which application threads were stopped: 0.0000975 seconds, Stopping threads took: 0.0000069 seconds
2019-10-29T10:00:28.976-0100: 0.585: Total time for which application threads were stopped: 0.0001414 seconds, Stopping threads took: 0.0000091 seconds
2019-10-29T10:00:28.982-0100: 0.590: [GC (Allocation Failure) 2019-10-29T10:00:28.982-0100: 0.590: [ParNew
Desired survivor size 1114112 bytes, new threshold 1 (max 6)
- age 1: 1669448 bytes, 1669448 total
: 19647K->2176K(19648K), 0.0032520 secs] 19854K->5036K(63360K), 0.0033060 secs] [Times: user=0.03 sys=0.00, real=0.00 secs]
即使是很短的时间，也可以提供很多信息。 您会看到分配失败，年轻的垃圾回收，正在停止的线程，垃圾回收前后的内存，每个事件都导致堆内存中对象的升级。
为什么垃圾收集日志很重要
处理应用程序性能调整可能是一个漫长而令人不愉快的经历。 我们需要适当地准备环境并观察应用程序。 进行检查以了解有关JVM性能调整的更多信息。 使用正确的可观察性工具，例如我们的Sematext Cloud ，您可以洞悉与应用程序，JVM和操作系统有关的关键指标 。
指标并不是全部。 即使是最好的APM工具也无法为您提供一切。 指标可以向您显示模式和历史数据，可以帮助您识别潜在的问题，但要能够看到需要更深入挖掘的一切。 就基于Java的应用程序而言，更深层次的是垃圾收集日志。 尽管GC日志非常冗长，但是它们提供的信息在其他来源中是不可用的，例如停止世界事件以及它们花费了多长时间，应用程序线程被停止了多长时间，内存池利用率等等。
如何启用GC日志记录
在讨论如何启用垃圾收集器日志记录之前，我们应该问自己一件事。 我应该默认打开日志还是仅在出现问题时才打开日志？ 在现代设备上，启用垃圾收集器日志时，您不必担心性能。 当然，由于日志必须写入某处，因此您将对持久性存储有更多的写入。 除此之外，日志不应在系统上产生任何额外的负载。
您应该始终打开Java垃圾收集日志。 实际上，许多开源系统已经在遵循这种做法。 例如，像Apache Solr或Elasticsearch这样的搜索系统已经包含了打开日志的JVM标志。 我们已经知道这些文件包含有关Java虚拟机操作的重要信息，因此我们知道为什么要打开它。
就如何激活Java 8和更低版本以及较新的Java版本的垃圾收集日志而言，有所不同。
对于Java 8和更早版本，应将以下标志添加到基于JVM的应用程序启动参数中：
-XX :+PrintGCDetails -Xloggc :<PATH_TO_GC_LOG_FILE>
其中PATH_TO_GC_LOG_FILE是垃圾收集器日志文件的位置。 例如：
java -XX :+PrintGCDetails -Xloggc :/var/log/myapp/gc.log -jar my_awesome_app.jar
在某些情况下，您还可以看到包含-XX：+ PrintGCTimeStamps 。 但是，这里是多余的，不需要。
对于Java 9和更高版本，您可以简化上面的命令，并将以下标志添加到应用程序启动参数：
-Xlog :gc * :file = <PATH_TO_GC_LOG_FILE>
例如：
java -Xlog :gc * :file = /var/log/myapp/gc.log -jar my_awesome_app.jar
启用日志后，记住GC日志轮换很重要。 使用较早的JVM版本（例如JDK 8）时，您可能需要旋转GC日志。 为此，我们有三个标志可以添加到我们的JVM应用程序启动参数中。 第一个是启用GC日志循环的标志： -XX：+ UseGCLogFileRotation 。 第二个属性-XX：NumberOfGCLogFiles告诉JVM应该保留多少个GC日志文件。 例如，包括-XX：NumberOfGCLogFiles = 10将启用最多10个GC日志文件。 最后， -XX：GCLogFileSize告诉您单个GC日志文件可以有多大。 例如， -XX：GCLogFileSize = 10m将在达到10 MB时旋转GC日志文件。
当使用JDK 11和G1GC垃圾收集器控制您的GC日志时，您将希望包含如下属性： java -Xlog：gc *：file = gc.log，filecount = 10，filesize = 10m 。 这将导致完全相同的行为。 我们将有多达10个GC日志文件，大小最大为10 MB。
既然我们知道了JVM垃圾收集器日志的重要性，并且默认情况下已将其打开，我们就可以开始分析它们了。
如何分析GC日志
了解垃圾收集日志并不容易。 它需要了解Java虚拟机的工作原理以及应用程序的内存使用情况。 在此博客文章中，我们将跳过对应用程序的分析，因为它因应用程序而异，并且需要了解代码。 不过，我们将讨论的是如何读取和分析我们可以从JVM中获得的垃圾收集日志。
同样重要的是，有各种JVM版本和多个垃圾回收器实现。 您仍然可以遇到Java 7、8、9等。 由于各种原因，一些公司仍使用Java 6。 每个版本可能正在运行不同的垃圾收集器-串行，并行，并发标记扫描，G1甚至甚至是Shenandoah或Z。您可以期望不同的Java版本和不同的垃圾收集器实现输出略有不同的日志格式，当然我们将不再讨论他们全部。 实际上，我们只会向您显示一小部分日志，但是这样也应该有助于您理解所有其他垃圾收集器日志。
垃圾收集日志将能够回答以下问题：
- 年轻一代的垃圾收集器何时使用？
- 上一代垃圾收集器何时使用？
- 运行了多少垃圾回收？
- 垃圾收集器运行了多长时间？
- 垃圾回收前后的内存利用率是多少？
现在，让我们看一下从JVM垃圾收集器日志中提取的示例，并分析每个片段以突出显示其背后的关键部分。
并行和并行标记扫描垃圾收集器
让我们先来看一下Java 8和Parallel收集器（用于年轻一代），以及Concurrent Mark Sweep垃圾收集器（用于老一代）。 来自我们的JVM垃圾收集器的一行如下所示：
2019-10-30T11:13:00.920-0100: 6.399: [Full GC (Allocation Failure) 2019-10-30T11:13:00.920-0100: 6.399: [CMS: 43711K->43711K(43712K), 0.1417937 secs] 63359K->48737K(63360K), [Metaspace: 47130K->47130K(1093632K)], 0.1418689 secs] [Times: user=0.14 sys=0.00, real=0.14 secs]
首先，您可以看到事件的日期和时间，在我们的例子中是2019–10–30T11：13：00.920–0100 。 这是事件发生的时间，这样您可以查看发生的情况和发生的时间。
我们在上面的日志行中可以看到的下一件事是垃圾回收的类型。 在我们的例子中，它是Full GC，您也可以在这里将GC作为一个值。 可能发生三种类型的垃圾收集器事件：
- 小垃圾收集
- 大型垃圾收集
- 完全垃圾收集
较小的垃圾回收意味着年轻空间清理事件是由JVM执行的。 当没有足够的内存来在堆上分配新对象时，即当Eden代已满或即将满时，次要垃圾收集器将始终被触发。 如果您的应用程序经常创建新对象，则可以期望次要垃圾收集器经常运行。 您应该记住的是，在少量垃圾回收期间，清理Eden和幸存者空间时，数据将被完全复制，这意味着不会发生内存碎片。
大型垃圾收集意味着执行了终身生成清除事件。 终身制一代也被广泛称为旧一代空间。 取决于垃圾收集器及其设置，使用年限较长的清洁可能会或多或少地发生。 哪个更好？ 正确的答案取决于用例，我们将不在此博客文章中讨论。
Java Full GC表示发生了完整的垃圾回收事件。 这意味着无论是年轻人和老一代已被清除。 垃圾收集器试图清除它，日志告诉我们该过程的结果。 终身清洁需要标记，清除和压缩阶段，以避免高内存碎片。 如果垃圾回收器不关心内存碎片，那么您可能会遇到以下情况：您有足够的内存，但是内存碎片化并且无法分配对象。 我们可以用下图说明这种情况：
还有一个我们没有讨论的部分-分配失败。 垃圾收集器日志行的“分配失败”部分说明了为什么垃圾收集周期开始。 通常，这意味着堆内存的Eden空间中没有剩余空间供新对象分配，垃圾回收器试图为新对象释放一些内存。 并发标记扫描垃圾回收器的标记阶段也可能生成分配失败。
日志行中的下一个重要事项是有关垃圾回收过程之前和之后内存占用的信息。 让我们再次更详细地研究该行：
您会看到该行包含许多有用的信息。 除了已经讨论过的内容外，我们还具有有关收集之前和之后的内存的信息。 我们有垃圾收集所花费的时间以及垃圾收集过程中使用的CPU资源。 如您所见，我们拥有许多信息，可让我们了解该过程的速度。
JVM垃圾收集器提供给我们的非常重要的信息之一是应用程序线程停止的总时间。 您可以期望线程会非常频繁地停止，但是会在很短的时间内停止。 例如：
2019-10-29T10:00:28.879-0100: 0.488: Total time for which application threads were stopped: 0.0001006 seconds, Stopping threads took: 0.0000065 seconds
您可以看到线程停止了0.0001006秒，线程停止花费了0.0000065秒。 线程停止的时间不长，您将在垃圾收集器日志中一遍又一遍地看到类似的信息。 应该引起危险的是较长的线程停止时间-也称为Stop the world事件，它将基本上停止您的应用程序。 这是一个例子：
2019-11-02T17:11:54.259-0100: 7.438: Total time for which application threads were stopped: 11.2305001 seconds, Stopping threads took: 0.5230011 seconds
在上面的日志行中，我们可以看到应用程序线程停止了11秒钟以上。 这意味着什么？ 基本上，您的应用程序响应时间不超过11秒。 它没有响应任何请求，没有处理数据，并且JVM仅在进行垃圾收集。 您想不惜一切代价避免这种情况。 这是大内存问题的迹象。 您的内存太低而无法正确执行应用程序的工作，或者您的内存泄漏会填满堆空间，最终导致很长的垃圾回收并最终导致内存不足。 这意味着您的应用程序将无法创建新对象，并且将停止工作。
G1垃圾收集器
现在让我们看一下G1垃圾收集器的外观。 我们将使用以下应用程序选项禁用先前使用的CMS垃圾收集器并打开G1GC：
- -XX：+ UseG1GC
- -XX：-UseConcMarkSweepGC
- -XX：-仅使用CMSInitiatingOccupancy
因此，我们打开了G1垃圾收集器并删除了并发标记扫描。
标准的G1垃圾收集器日志条目如下所示：
2019-11-03T21:26:21.827-0100: 2.069: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 2097152 bytes, new threshold 15 (max 15)
- age 1: 341608 bytes, 341608 total
, 0.0021740 secs]
[Parallel Time: 0.9 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 2069.4, Avg: 2069.5, Max: 2069.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.1, Avg: 0.2, Max: 0.4, Diff: 0.3, Sum: 1.5]
[Update RS (ms): Min: 0.1, Avg: 0.2, Max: 0.3, Diff: 0.2, Sum: 2.3]
[Processed Buffers: Min: 1, Avg: 1.4, Max: 4, Diff: 3, 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.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 0.2, Avg: 0.3, Max: 0.3, Diff: 0.1, Sum: 3.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 10]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Total (ms): Min: 0.6, Avg: 0.7, Max: 0.8, Diff: 0.1, Sum: 7.0]
[GC Worker End (ms): Min: 2070.2, Avg: 2070.2, Max: 2070.2, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.2 ms]
[Other: 1.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.8 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.0 ms]
[Eden: 26.0M(26.0M)->0.0B(30.0M) Survivors: 5120.0K->3072.0K Heap: 51.4M(64.0M)->22.6M(64.0M)]
[Times: user=0.01 sys=0.00, real=0.01 secs]
在上面的日志行中，您可以看到我们发生了一个年轻的垃圾回收事件[GC暂停（G1疏散暂停）（年轻） ，这导致清除了某些内存区域： [Eden：26.0M（26.0M）-> 0.0 B（30.0M）幸存者：5120.0K-> 3072.0K堆：51.4M（64.0M）-> 22.6M（64.0M）] 。 我们还提供了时间信息和CPU使用率[时间：user = 0.01 sys = 0.00，real = 0.01 secs] 。 这些时间与前面的垃圾收集器讨论中的时间完全相同。 在垃圾回收过程中，用户和系统范围的CPU使用率已经确定。
详细的内存信息摘要为我们提供了所发生情况的概述。 我们可以看到Eden空间已完全清除Eden： 26.0M（26.0M）-> 0.0B（30.0M） 。 当垃圾收集被26M数据占用时，垃圾收集开始。 垃圾收集之后，我们以一个完全空的Eden空间结束。 垃圾回收时，Eden空间的总大小为30MB。 垃圾收集从幸存者的空间开始，该空间有5120K的内存，最后以3072K的数据结束。 最后，整个堆从占64M总大小中的51.4M开始，到占22.6M为止。
除此之外，您还将看到有关并行垃圾收集器工作程序内部和工作阶段的更多详细信息，例如启动，扫描和工作。
您还可以看到与G1垃圾收集器相关的其他日志条目：
2019-11-03T21:26:23.704-0100: 2019-11-03T21:26:23.704-0100: 3.946: 3.946: [GC concurrent-root-region-scan-start]
Total time for which application threads were stopped: 0.0035771 seconds, Stopping threads took: 0.0000111 seconds
2019-11-03T21:26:23.706-0100: 3.948: [GC concurrent-root-region-scan-end, 0.0017994 secs]
2019-11-03T21:26:23.706-0100: 3.948: [GC concurrent-mark-start]
2019-11-03T21:26:23.737-0100: 3.979: [GC concurrent-mark-end, 0.0315921 secs]
2019-11-03T21:26:23.737-0100: 3.979: [GC remark 2019-11-03T21:26:23.737-0100: 3.979: [Finalize Marking, 0.0002017 secs] 2019-11-03T21:26:23.738-0100: 3.980: [GC ref-proc, 0.0004151 secs] 2019-11-03T21:26:23.738-0100: 3.980: [Unloading, 0.0025065 secs], 0.0033738 secs]
[Times: user=0.04 sys=0.01, real=0.01 secs]
2019-11-03T21:26:23.741-0100: 3.983: Total time for which application threads were stopped: 0.0034705 seconds, Stopping threads took: 0.0000308 seconds
2019-11-03T21:26:23.741-0100: 3.983: [GC cleanup 54M->54M(64M), 0.0004419 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
当然，上面的日志行是不同的，但是原理仍然存在。 该日志为我们提供了有关应用程序线程停止的总时间，垃圾收集器进行清理的结果以及所用资源的信息。
Java 9和更高版本中的GC日志记录选项
我们甚至可以更深入地进行垃圾回收并打开调试级别。 让我们以Java 10为例，并将-Xlog：gc *，gc + phases = debug包含在JVM的启动参数中。 这将打开Java 10上默认G1垃圾收集器的垃圾收集阶段的调试级别日志记录。这将启用详细的GC日志记录，为您提供有关垃圾收集器工作的大量信息。
[0.006s][info][gc,heap] Heap region size: 1M
[0.012s][info][gc ] Using G1
[0.013s][info][gc,heap,coops] Heap address: 0x00000006c0000000, size: 4096 MB, Compressed Oops mode: Zero based, Oop shift amount: 3
[0.428s][info][gc,start ] GC(0) Pause Young (G1 Evacuation Pause)
[0.428s][info][gc,task ] GC(0) Using 2 workers of 2 for evacuation
[0.432s][info][gc,phases ] GC(0) Pre Evacuate Collection Set: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Prepare TLABs: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Choose Collection Set: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Humongous Register: 0.0ms
[0.433s][info ][gc,phases ] GC(0) Evacuate Collection Set: 3.8ms
[0.433s][debug][gc,phases ] GC(0) Ext Root Scanning (ms): Min: 0.6, Avg: 0.7, Max: 0.8, Diff: 0.2, Sum: 1.4, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Claimed Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.1, Workers: 2
[0.433s][debug][gc,phases ] GC(0) AOT Root Scanning (ms): skipped
[0.433s][debug][gc,phases ] GC(0) Object Copy (ms): Min: 2.8, Avg: 2.9, Max: 3.0, Diff: 0.2, Sum: 5.7, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2, Workers: 2
[0.433s][debug][gc,phases ] GC(0) GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[0.433s][debug][gc,phases ] GC(0) GC Worker Total (ms): Min: 3.6, Avg: 3.6, Max: 3.7, Diff: 0.1, Sum: 7.3, Workers: 2
[0.433s][info ][gc,phases ] GC(0) Post Evacuate Collection Set: 0.1ms
[0.433s][debug][gc,phases ] GC(0) Code Roots Fixup: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Preserve CM Refs: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Reference Processing: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Clear Card Table: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Reference Enqueuing: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Merge Per-Thread State: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Code Roots Purge: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Redirty Cards: 0.0ms
[0.433s][debug][gc,phases ] GC(0) DerivedPointerTable Update: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Free Collection Set: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Humongous Reclaim: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Start New Collection Set: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Resize TLABs: 0.0ms
[0.433s][debug][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms
[0.433s][info ][gc,phases ] GC(0) Other: 0.2ms
[0.433s][info ][gc,heap ] GC(0) Eden regions: 7->0(72)
[0.433s][info ][gc,heap ] GC(0) Survivor regions: 0->1(1)
[0.433s][info ][gc,heap ] GC(0) Old regions: 0->1
[0.433s][info ][gc,heap ] GC(0) Humongous regions: 6->3
[0.433s][info ][gc,metaspace ] GC(0) Metaspace: 9281K->9281K(1058816K)
[0.433s][info ][gc ] GC(0) Pause Young (G1 Evacuation Pause) 13M->4M(122M) 4.752ms
[0.433s][info ][gc,cpu ] GC(0) User=0.00s Sys=0.01s Real=0.00s
您可以在上面的日志行的突出显示部分中看到确切的时间安排。 它们不在我们前面讨论的G1垃圾收集器日志中。 当然，阶段不是您可以打开的唯一选项。 这些是Java 9可用的选项，在这里与已删除或不建议使用的标志相对应。 以下是早期Java虚拟机版本中可用的一些选项，以及它们在Java 9及更高版本中转换为的选项：
- -XX：+ PrintHeapAtGC现在可以表示为-Xlog：gc + heap = debug选项
- -XX：+ PrintParallelOldGCPhases时间可以表示为-Xlog：gc + phases * = trace
- -XX：+ PrintGCApplicationConcurrentTime和-XX：+ PrintGCApplicationStoppedTime现在可以表示为-Xlog：safepoint
- -XX：+ G1PrintHeapRegions可以表示为-Xlog：gc + region * = trace
- -XX：+ SummarizeConcMark可以表示为-Xlog：gc + marking * = trace
- -XX：+ SummarizeRSetStats可以表示为-Xlog：gc + remset * = trace
- -XX：+ PrintJNIGC停转可以表示为-Xlog：gc + jni * = debug
- -XX：+ PrintTaskqueue可以表示为-Xlog：gc + task + stats * = trace
- -XX：+ TraceDynamicGCThreads可以表示为-Xlog：gc + task * = trace
- -XX：+ PrintAdaptiveSizePolicy可以表示为-Xlog：gc + ergo * = trace
- -XX：+ PrintTenuringDistribution可以表示为-Xlog：gc + age * = trace
您可以组合多个选项或通过将-Xlog：all = trace标志添加到JVM应用程序启动参数来启用所有选项。 但是请注意，它可能导致垃圾收集器日志文件中包含大量信息。 为了避免信息泛滥，您可以使用-Xlog：all = debug将其设置为调试-它会减少信息量，但比标准垃圾收集器日志提供更多的信息。
Java垃圾收集日志：您需要了解的日志分析工具
有日志分析工具可以帮助您分析垃圾收集器日志。 但是，标准Java虚拟机发行版中没有可用的开箱即用产品。
APM和可观察性工具
当涉及到对Java垃圾收集器性能的高级概述时，可以使用提供Java应用程序级监视的一种可观察性工具。例如，由Sematext Cloud提供的我们自己的Sematext JVM Monitoring 。
这样的工具应该为您提供有关垃圾收集器的工作方式，时间，收集次数，最大收集时间和平均收集大小的摘要信息。 在大多数情况下，这足以发现垃圾收集问题，而无需深入研究日志并进行分析。
但是，在进行故障排除时，您可能需要对JVM中的垃圾收集器内部发生的事情有更细粒度的了解。 如果您不想手动分析数据，则可以使用一些工具来帮助您。
GCViewer
例如，可以帮助您可视化GC日志的工具之一就是GCViewer 。 该工具可分析高达Java 1.5的垃圾收集器日志及其延续性，以支持较新的Java版本和G1垃圾收集器。
GC Viewer旨在提供有关内存利用率和整体垃圾收集器进程的全面信息。 它是开源的，并且完全免费供个人和商业使用，旨在提供对Java 8以及更高版本的支持，并为OpenJDK 9和10提供统一的日志记录。
GCEasy
也有专有和商业工具。 其中之一是GCEasy 。 这是一个在线GC日志分析器工具，您可以在其中上传垃圾收集日志并以易于阅读的日志分析报告的形式获取结果：
该报告将包括诸如生成大小和最大大小之类的信息，诸如平均和最大暂停时间之类的关键性能指标，暂停统计信息，内存泄漏信息以及向您显示每个堆内存空间的交互式图表。 所有这些信息都是根据您提供的日志文件计算的。
即使GCEasy有免费计划，它也受到限制。 在撰写本文时，一个用户每月可以上传5个GC日志文件，每个文件最多50mb。 如果您有兴趣使用该工具，则可以使用其他计划。
包起来
了解垃圾收集器日志并不容易。 大量可能的格式，不同的Java虚拟机版本以及不同的垃圾收集器实现方式并没有使其变得更简单。 即使您要记住很多选择，但某些部分还是很常见的。 每个垃圾收集器都会告诉您堆的大小，即被清除的堆区域的占用前后。 最后，您还将看到执行操作所需的时间和资源。 从此开始，然后继续理解JVM垃圾收集过程和应用程序的内存使用的过程。 快乐分析：）
From: https://dev.to/sematext/java-garbage-collection-logs-how-to-analyze-them-4hgb
885
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
