开启语句
JAVA_OPTS="-XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-Xloggc:/Logs/**web/gc.log -XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=3 -XX:GCLogFileSize=512k"
参数详解
-XX:UseGCLogFileRotation
Enabled GC log rotation, requires -Xloggc.
打开或关闭GC日志滚动记录功能,要求必须设置 -Xloggc参数-XX:NumberOfGCLogFiles
Set the number of files to use when rotating logs, must be >= 1.
The rotated log files will use the following naming scheme, <filename>.0, <filename>.1, ..., <filename>.n-1.
设置滚动日志文件的个数,必须大于等于1
日志文件命名策略是,<filename>.0, <filename>.1, ..., <filename>.n-1,其中n是该参数的值-XX:GCLogFileSize
The size of the log file at which point the log will be rotated, must be >= 8K.
设置滚动日志文件的大小,必须大于8k
当前写日志文件大小超过该参数值时,日志将写入下一个文件-XX:+PrintGCDetails
输出GC的详细日志-XX:+PrintGCTimeStamps
输出GC的时间戳(以基准时间的形式)
日志实例
Java HotSpot(TM) 64-Bit Server VM (25.181-b13) for linux-amd64 JRE (1.8.0_181-b13), built on Jul 7 2018 00:56:38 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 8193428k(3496440k free), swap 0k(0k free)
CommandLine flags: -XX:GCLogFileSize=524288 -XX:InitialHeapSize=4294967296 -XX:+ManagementServer -XX:MaxHeapSize=4294967296 -XX:NumberOfGCLogFiles=3 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseGCLogFileRotation -XX:+UseParallelGC
42.198: [GC (Metadata GC Threshold) [PSYoungGen: 734017K->104550K(1223168K)] 734017K->104558K(4019712K), 0.1290021 secs] [Times: user=0.21 sys=0.04, real=0.13 secs]
42.327: [Full GC (Metadata GC Threshold) [PSYoungGen: 104550K->0K(1223168K)] [ParOldGen: 8K->99343K(2796544K)] 104558K->99343K(4019712K), [Metaspace: 20690K->20690K(1069056K)], 0.2324920 secs] [Times: user=0.42 sys=0.04, real=0.24 secs]
45.761: [GC (Metadata GC Threshold) [PSYoungGen: 233830K->23741K(1223168K)] 333173K->123085K(4019712K), 0.0325270 secs] [Times: user=0.04 sys=0.01, real=0.03 secs]
45.794: [Full GC (Metadata GC Threshold) [PSYoungGen: 23741K->0K(1223168K)] [ParOldGen: 99343K->43223K(2796544K)] 123085K->43223K(4019712K), [Metaspace: 34569K->34569K(1081344K)], 0.0938388 secs] [Times: user=0.16 sys=0.00, real=0.09 secs]
50.471: [GC (Allocation Failure) [PSYoungGen: 1048576K->52261K(1223168K)] 1091799K->95493K(4019712K), 0.0936524 secs] [Times: user=0.18 sys=0.00, real=0.09 secs]
52.972: [GC (Allocation Failure) [PSYoungGen: 1100837K->132083K(1223168K)] 1144069K->175314K(4019712K), 0.1152273 secs] [Times: user=0.12 sys=0.04, real=0.11 secs]
54.338: [GC (Metadata GC Threshold) [PSYoungGen: 269492K->50369K(1223168K)] 312723K->93600K(4019712K), 0.0515360 secs] [Times: user=0.09 sys=0.00, real=0.05 secs]
54.389: [Full GC (Metadata GC Threshold) [PSYoungGen: 50369K->0K(1223168K)] [ParOldGen: 43231K->74678K(2796544K)] 93600K->74678K(4019712K), [Metaspace: 57882K->57882K(1101824K)], 0.3388499 secs] [Times: user=0.63 sys=0.00, real=0.34 secs]
200.593: [GC (Allocation Failure) [PSYoungGen: 1048576K->112285K(1228800K)] 1123254K->186972K(4025344K), 0.0848518 secs] [Times: user=0.14 sys=0.00, real=0.08 secs]
967.476: [GC (Allocation Failure) [PSYoungGen: 1193629K->158202K(1239552K)] 1268316K->390011K(4036096K), 0.1867644 secs] [Times: user=0.17 sys=0.06, real=0.19 secs]
1784.942: [GC (Allocation Failure) [PSYoungGen: 1239546K->158194K(866816K)] 1471355K->567095K(3663360K), 0.1974644 secs] [Times: user=0.20 sys=0.06, real=0.20 secs]
2350.420: [GC (Allocation Failure) [PSYoungGen: 866787K->247284K(948224K)] 1275688K->656193K(3744768K), 0.1324127 secs] [Times: user=0.19 sys=0.00, real=0.13 secs]
2915.003: [GC (Allocation Failure) [PSYoungGen: 948212K->247882K(1002496K)] 1357121K->656799K(3799040K), 0.1264757 secs] [Times: user=0.18 sys=0.00, real=0.13 secs]
3439.324: [GC (Allocation Failure) [PSYoungGen: 884810K->233402K(863744K)] 1293727K->642327K(3660288K), 0.1219719 secs] [Times: user=0.17 sys=0.00, real=0.13 secs]
日志分析
例如:
1784.942: [GC (Allocation Failure) [PSYoungGen: 1239546K->158194K(866816K)]
1471355K->567095K(3663360K), 0.1974644 secs] [Times: user=0.20 sys=0.06, real=0.20 secs]
在1784.942时间点,年轻代进行了mini gc,从1239M经过垃圾收集后变为了158M
堆内存从1471M变为567M,堆最大内存为:3.6个G。
user=0.20代表所有cup使用的时间,这个时间比 real=0.20时间大,证明是多个线程进行垃圾回收。