JVM G1 GC日志分析

Question

请帮忙检查一下为什么我的GC日志生成失败，或者有什么问题。

我的java启动参数是

-Xms5G -Xmx5G -Xss1024K 
-XX:+UseG1GC -XX:MaxGCPauseMillis=200 -XX:G1HeapRegionSize=4m  

-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps 
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:-PrintCommandLineFlags 
-XX:+PrintAdaptiveSizePolicy -XX:+PrintTenuringDistribution -XX:+PrintReferenceGC 
-Xloggc:/data/gclog/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M

我设置了一个循环来生成 JVM G1 GC 日志。这是我第一次使用 G1 GC。但它总是创建一个内容很少的日志 "gc.0.current"，"gc" 是日志的名称。内容如下。

Java HotSpot(TM) 64-Bit Server VM (25.73-b02) for linux-amd64 JRE (1.8.0_73-b02), built on Jan 29 2016 17:39:45 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8056924k(5058272k free), swap 4194300k(4194300k free)
CommandLine flags: -XX:G1HeapRegionSize=4194304 -XX:GCLogFileSize=104857600 -XX:InitialHeapSize=5368709120 -XX:MaxGCPauseMillis=200 -XX:MaxHeapSize=5368709120 -XX:NumberOfGCLogFiles=5 -XX:+PrintAdaptiveSizePolicy -XX:-PrintCommandLineFlags -XX:+PrintGC -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:+PrintTenuringDistribution -XX:ThreadStackSize=1024 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:+UseGCLogFileRotation
 0.012: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 5368709120 bytes, attempted expansion amount: 5368709120 bytes]
2019-08-21T23:23:26.706-0500: 0.212: Application time: 0.1403261 seconds
2019-08-21T23:23:26.706-0500: 0.212: Total time for which application threads were stopped: 0.0001008 seconds, Stopping threads took: 0.0000202 seconds
Heap
 garbage-first heap   total 5242880K, used 8192K [0x0000000680000000, 0x0000000680402800, 0x00000007c0000000)
  region size 4096K, 3 young (12288K), 0 survivors (0K)
 Metaspace       used 7309K, capacity 7452K, committed 7552K, reserved 1056768K
  class space    used 853K, capacity 888K, committed 896K, reserved 1048576K
2019-08-21T23:23:26.775-0500: 0.281: Application time: 0.0686930 seconds

没有创建其他日志。你知道这是为什么吗？我在服务器上有运行很多任务，假设它应该生成一些 GC 日志。

从上面的日志内容可以看出有什么异常吗？

有没有其他方法可以查看 Linux 服务器上的 GC 活动？

谢谢，

Answer 1

我在简单的 CRUD 服务上测试了所有参数，没有问题。但是当我测试Hello world应用程序时，打印的日志和你的一样，因为没有触发GC。当我在 Hello World 应用程序上使用 System.gc() 手动触发 GC 时，打印了 GC 日志。

综上所述，如果GC不做任何动作，log不打印。

Answer 2

可能是 -XX:+UseGCLogFileRotation 的问题。我之前遇到过同样的问题，这对我有用：

-Xloggc:/data/gclog/gc

而不是

-Xloggc:/data/gclog/gc -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=100M

这是我在生产环境中调整 G1GC 时的笔记，希望您能找到一些有用的信息：How Garbage First Garbage Collector (G1GC) affected the performance of our back-end。

还有一个建议给Avoid -XX:+UseGCLogFileRotation. One GC log file would be easier to be imported to analysing tools like GC Viewer。

Answer 3

打印在 GC 日志底部的堆布局表明您的 Java 进程已终止。

堆布局在两种情况下打印：before/after GC，如果指定了-XX:+PrintHeapAtGC，以及JVM退出之前。你的情况显然是后者。

JVM 几乎在启动后立即退出（运行仅持续了 281 毫秒）。最有可能的是，它无法启动应用程序（检查 VM 输出），或者它做了一些非常简单的事情，即刚刚启动了一个新的子进程。

请注意，一个新的 JVM 进程 overwrites 先前写入的日志文件。

JVM G1 GC日志分析

JVM G1 GC logs analyze

java

jvm

jvm-hotspot

jvm-arguments