相关FLAG
-XX:+PrintGC
开启简单GC日志模式,例:
[GC 246656K->243120K(376320K), 0.0929090 secs] #堆空间从246656K减少到243120K,耗时0.0929090
[Full GC 243120K->241951K(629760K), 1.5589690 secs] #
-XX:PrintGCDetails
开启详细GC日志模式,日志格式根据使用的GC算法各不相同
-XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps
打印GC发生的时间,一个是jvm启动时间,一个是真实的时间
- PrintGCTimeStamps
10828.000: [GC (Allocation Failure) 2019-11-04T17:52:07.130+0800: 10828.000: [ParNew
- PrintGCDateStamps
2019-11-04T17:52:07.130+0800: [GC (Allocation Failure)
-Xloggc:file -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1M
loggc:file
将GC日志输出到文件中,后边的几个选项是开启滚动日志,也就是将日志按大小分割,实际上GC日志文件不是太大,不必要开启日志滚动。
-XX:+PrintGCCause
产生GC的原因,在JDK8已默认打开
-XX:+PrintPromotionFailure
如果有新生代对象晋升到老生代失败出现的FULL GC,打开这个日志可以看到更详细的信息
-XX:+PrintGCApplicationStoppedTime
GC日志格式
jstat -gcutil
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
10.40 0.00 47.03 72.53 98.19 95.76 251776 3272.123 14 0.698 3272.821
幸存区1 幸存区2 eden 老年代 元数据区 CCS使用率 YGC次数 YGC总时间 FGC次数 FGC总时间 总GC时间
CCS即 CompressedClassSpace 压缩类空间
java8移除了permanent generation,然后class metadata存储在native memory中,其大小默认是不受限的,可以通过-XX:MaxMetaspaceSize来限制;如果开启了-XX:+UseCompressedOops及-XX:+UseCompressedClassesPointers(默认是开启),则UseCompressedOops会使用32-bit的offset来代表java object的引用,而UseCompressedClassPointers则使用32-bit的offset来代表64-bit进程中的class pointer;可以使用CompressedClassSpaceSize来设置这块的空间大小
参考聊聊jvm的CompressedClassSpace
- ParNew GC日志格式,flag为
-Xloggc:filexx -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintPromotionFailure -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCTimeStamps
时的日志格式示例:
{Heap before GC invocations=4 (full 0):#已发生GC次数,FULL GC次数0
#GC前年轻代堆内存使用情况,年轻代总大小1887488K,已使用1727926K
par new generation total 1887488K, used 1727926K [0x0000000660800000, 0x00000006e0800000, 0x00000006e0800000)
#年轻代三个区域的内存使用情况
eden space 1677824K, 100% used [0x0000000660800000, 0x00000006c6e80000, 0x00000006c6e80000)
from space 209664K, 23% used [0x00000006c6e80000, 0x00000006c9f6d878, 0x00000006d3b40000)
to space 209664K, 0% used [0x00000006d3b40000, 0x00000006d3b40000, 0x00000006e0800000)
#老年代内存使用情况,总大小4194304K,已使用18438K
concurrent mark-sweep generation total 4194304K, used 18438K [0x00000006e0800000, 0x00000007e0800000, 0x00000007e0800000)
#元数据区 参见 https://www.cnblogs.com/benwu/articles/8312699.html
Metaspace used 34624K, capacity 35104K, committed 35456K, reserved 1081344K
class space used 4253K, capacity 4365K, committed 4480K, reserved 1048576K
#GC发生时间,65493.227是GC发生时的jvm时间也就是nanotime GC发生的原因是Allocation Failure GC类型是ParNew
2019-12-24T09:46:35.442+0800: 65493.227: [GC (Allocation Failure) 2019-12-24T09:46:35.442+0800: 65493.227: [ParNew
#晋升阈值是3,也就是对象熬过的ygc次数,各个年龄(ygc次数)代的对象大小
#desired survivor size = (survivor区容量 * TargetSurvivorRatio)/100(TargetSurvivorRatio默认是50),是个固定值
Desired survivor size 107347968 bytes, new threshold 3 (max 3)
- age 1: 32349728 bytes, 32349728 total
- age 2: 9736 bytes, 32359464 total
- age 3: 9528 bytes, 32368992 total
#年轻代使用量从1727926K减少到了35459K,总大小是1887488K,堆使用量从1746364K减少到了55013K(总大小是6081792K),GC耗时0.0566931s
: 1727926K->35459K(1887488K), 0.0565661 secs] 1746364K->55013K(6081792K), 0.0566931 secs] [Times: user=0.31 sys=0.02, real=0.05 secs]
# 这部分和开始处格式一样
Heap after GC invocations=5 (full 0):
par new generation total 1887488K, used 35459K [0x0000000660800000, 0x00000006e0800000, 0x00000006e0800000)
eden space 1677824K, 0% used [0x0000000660800000, 0x0000000660800000, 0x00000006c6e80000)
from space 209664K, 16% used [0x00000006d3b40000, 0x00000006d5de0cd0, 0x00000006e0800000)
to space 209664K, 0% used [0x00000006c6e80000, 0x00000006c6e80000, 0x00000006d3b40000)
concurrent mark-sweep generation total 4194304K, used 19553K [0x00000006e0800000, 0x00000007e0800000, 0x00000007e0800000)
Metaspace used 34624K, capacity 35104K, committed 35456K, reserved 1081344K
class space used 4253K, capacity 4365K, committed 4480K, reserved 1048576K
}
- CMS 日志格式
#初始标记阶段,会stop the world 老年代已使用3145728K(总4194304K),整个堆已使用3179746K(总堆6081792K)
2020-03-25T21:49:54.257+0800: 1142819.594: [GC (CMS Initial Mark) [1 CMS-initial-mark: 3145728K(4194304K)] 3179746K(6081792K), 0.0058716 secs] [Times: user=0.02 sys=0.02, real=0.00 secs]
# 并发标记阶段,不会stw
2020-03-25T21:49:54.263+0800: 1142819.600: [CMS-concurrent-mark-start]
2020-03-25T21:49:55.002+0800: 1142820.339: [CMS-concurrent-mark: 0.739/0.739 secs] [Times: user=2.36 sys=1.91, real=0.74 secs]
# 并发预清理阶段,不会stw
2020-03-25T21:49:55.002+0800: 1142820.340: [CMS-concurrent-preclean-start]
2020-03-25T21:49:55.016+0800: 1142820.353: [CMS-concurrent-preclean: 0.014/0.014 secs] [Times: user=0.01 sys=0.02, real=0.02 secs]
2020-03-25T21:49:55.017+0800: 1142820.354: [CMS-concurrent-abortable-preclean-start]
CMS: abort preclean due to time 2020-03-25T21:50:00.143+0800: 1142825.480: [CMS-concurrent-abortable-preclean: 5.121/5.126 secs] [Times: user=11.02 sys=0.00, real=5.12 secs]
# 重新标记阶段,会stw,也是最耗时的阶段,CMS导致的应用暂停基本都是这个阶段,可以看到耗时100ms
2020-03-25T21:50:00.149+0800: 1142825.486: [GC (CMS Final Remark) [YG occupancy: 652003 K (1887488 K)]2020-03-25T21:50:00.149+0800: 1142825.486: [Rescan (parallel) , 0.0716031 secs]2020-03-25T21:50:00.220+0800: 1142825.558: [weak refs processing, 0.0022247 secs]2020-03-25T21:50:00.223+0800: 1142825.560: [class unloading, 0.0164177 secs]2020-03-25T21:50:00.239+0800: 1142825.576: [scrub symbol table, 0.0070541 secs]2020-03-25T21:50:00.246+0800: 1142825.583: [scrub string table, 0.0009672 secs][1 CMS-remark: 3145728K(4194304K)] 3797731K(6081792K), 0.0992188 secs] [Times: user=0.00 sys=0.00, real=0.10 secs]
# 并发清除阶段,不会stw
2020-03-25T21:50:00.248+0800: 1142825.586: [CMS-concurrent-sweep-start]
2020-03-25T21:50:02.408+0800: 1142827.745: [CMS-concurrent-sweep: 2.159/2.159 secs] [Times: user=2.30 sys=0.39, real=2.16 secs]
# 并发重置阶段,不会stw
2020-03-25T21:50:02.408+0800: 1142827.745: [CMS-concurrent-reset-start]
2020-03-25T21:50:02.419+0800: 1142827.756: [CMS-concurrent-reset: 0.011/0.011 secs] [Times: user=0.00 sys=0.01, real=0.01 secs]
安全点日志
-XX:+PrintSafepointStatistics
-XX: PrintSafepointStatisticsCount=1
-XX:+UnlockDiagnosticVMOptions
-XX:- DisplayVMOutput
-XX:+LogVMOutput
-XX:LogFile=myapp.log
开启JMX
-Dcom.sun.management.jmxremote.port=7001
-Dcom.sun.management.jmxremote
-Dcom.sun.management.jmxremote.authenticate=false
-Dcom.sun.management.jmxremote.ssl=false
-Djava.rmi.server.hostname=127.0.0.1