grok 获取java日志 jvm gc日志开启

转载

mob6454cc7416d1 2023-10-11 16:35:15

文章标签 grok 获取java日志 java jvm sed Time 文章分类 Java 后端开发

Gc优化

内存被使用了之后，难免会有不够用或者达到设定值的时候，就需要对内存空间进行垃圾回收。

垃圾收集发生的时机

GC是由JVM自动完成的，根据JVM系统环境而定，所以时机是不确定的。当然，我们可以手动进行垃圾回收，

比如调用System.gc()方法通知JVM进行一次垃圾回收，但是具体什么时刻运行也无法控制。也就是说

System.gc()只是通知要回收，什么时候回收由JVM决定。但是不建议手动调用该方法，因为消耗的资源比较

大。

一般以下几种情况会发生垃圾回收

（1）当Eden区或者S区不够用了

（2）老年代空间不够用了

（3）方法区空间不够用了

（4）System.gc()

GC日志文件

基于java8分析

链接: https://pan.baidu.com/s/1rA7HtR2g-MNwzogv3ZJqeQ 提取码: p6ca

grok 获取java日志 jvm gc日志开启_java

要想分析日志的信息，得先拿到GC日志文件才行，所以得先配置一下，之前也看过这些参数

-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -Xloggc:gc.log

启动项目

Parallel GC日志

吞吐量优先

java8 默认使用Parallel Scavenge+Paralled Old

Java HotSpot(TM) 64-Bit Server VM (25.211-b12) for bsd-amd64 JRE (1.8.0_211-b12), built on Apr  1 2019 20:53:18 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 33554432k(1676620k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=8589934592 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC 
2022-01-11T19:08:46.032-0800: 1.593: [GC (Allocation Failure) [PSYoungGen: 131584K->13213K(153088K)] 131584K->13229K(502784K), 0.0149631 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2022-01-11T19:08:46.114-0800: 1.674: [GC (Metadata GC Threshold) [PSYoungGen: 27621K->5732K(153088K)] 27637K->5756K(502784K), 0.0068344 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2022-01-11T19:08:46.121-0800: 1.681: [Full GC (Metadata GC Threshold) [PSYoungGen: 5732K->0K(153088K)] [ParOldGen: 24K->5583K(167936K)] 5756K->5583K(321024K), [Metaspace: 20603K->20603K(1067008K)], 0.0241968 secs] [Times: user=0.08 sys=0.01, real=0.02 secs] 
2022-01-11T19:08:47.061-0800: 2.621: [GC (Allocation Failure) [PSYoungGen: 131584K->12344K(153088K)] 137167K->17936K(321024K), 0.0064436 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 
2022-01-11T19:08:48.485-0800: 4.045: [GC (Allocation Failure) [PSYoungGen: 143928K->17945K(237056K)] 149520K->23608K(404992K), 0.0140764 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2022-01-11T19:08:49.315-0800: 4.875: [GC (Metadata GC Threshold) [PSYoungGen: 174411K->21496K(242688K)] 180074K->28179K(410624K), 0.0172624 secs] [Times: user=0.05 sys=0.02, real=0.02 secs] 
2022-01-11T19:08:49.332-0800: 4.892: [Full GC (Metadata GC Threshold) [PSYoungGen: 21496K->0K(242688K)] [ParOldGen: 6682K->25984K(262656K)] 28179K->25984K(505344K), [Metaspace: 33869K->33869K(1079296K)], 0.0925447 secs] [Times: user=0.31 sys=0.02, real=0.09 secs] 
Heap
 PSYoungGen      total 242688K, used 59499K [0x0000000715580000, 0x000000072e780000, 0x00000007c0000000)
  eden space 221184K, 26% used [0x0000000715580000,0x0000000718f9aef0,0x0000000722d80000)
  from space 21504K, 0% used [0x0000000722d80000,0x0000000722d80000,0x0000000724280000)
  to   space 26112K, 0% used [0x000000072ce00000,0x000000072ce00000,0x000000072e780000)
 ParOldGen       total 262656K, used 25984K [0x00000005c0000000, 0x00000005d0080000, 0x0000000715580000)
  object space 262656K, 9% used [0x00000005c0000000,0x00000005c1960270,0x00000005d0080000)
 Metaspace       used 35271K, capacity 36842K, committed 36992K, reserved 1081344K
  class space    used 4848K, capacity 5147K, committed 5248K, reserved 1048576K

注意如果回收的差值中间有出入，说明这部分空间是Old区释放出来的

CMS日志

【停顿时间优先】

参数设置：-XX:+UseConcMarkSweepGC -Xloggc:cms-gc.log

使用 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC

Java HotSpot(TM) 64-Bit Server VM (25.211-b12) for bsd-amd64 JRE (1.8.0_211-b12), built on Apr  1 2019 20:53:18 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 33554432k(940564k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=8589934592 -XX:MaxNewSize=697933824 -XX:MaxTenuringThreshold=6 -XX:OldPLABSize=16 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC 
2022-01-11T19:14:54.684-0800: 1.418: [GC (Allocation Failure) 2022-01-11T19:14:54.684-0800: 1.418: [ParNew: 139776K->13890K(157248K), 0.0127240 secs] 139776K->13890K(506816K), 0.0129656 secs] [Times: user=0.04 sys=0.01, real=0.01 secs] 
2022-01-11T19:14:54.698-0800: 1.431: [GC (CMS Initial Mark) [1 CMS-initial-mark: 0K(349568K)] 16686K(506816K), 0.0023723 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
2022-01-11T19:14:54.700-0800: 1.433: [CMS-concurrent-mark-start]
2022-01-11T19:14:54.701-0800: 1.434: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-01-11T19:14:54.701-0800: 1.434: [CMS-concurrent-preclean-start]
2022-01-11T19:14:54.703-0800: 1.436: [CMS-concurrent-preclean: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-01-11T19:14:54.703-0800: 1.437: [CMS-concurrent-abortable-preclean-start]
2022-01-11T19:14:55.111-0800: 1.845: [CMS-concurrent-abortable-preclean: 0.170/0.408 secs] [Times: user=0.79 sys=0.08, real=0.41 secs] 
2022-01-11T19:14:55.112-0800: 1.845: [GC (CMS Final Remark) [YG occupancy: 86083 K (157248 K)]2022-01-11T19:14:55.112-0800: 1.845: [Rescan (parallel) , 0.0087525 secs]2022-01-11T19:14:55.120-0800: 1.854: [weak refs processing, 0.0000350 secs]2022-01-11T19:14:55.120-0800: 1.854: [class unloading, 0.0019295 secs]2022-01-11T19:14:55.122-0800: 1.856: [scrub symbol table, 0.0026388 secs]2022-01-11T19:14:55.125-0800: 1.858: [scrub string table, 0.0003238 secs][1 CMS-remark: 0K(349568K)] 86083K(506816K), 0.0144971 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
2022-01-11T19:14:55.126-0800: 1.860: [CMS-concurrent-sweep-start]
2022-01-11T19:14:55.126-0800: 1.860: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
2022-01-11T19:14:55.126-0800: 1.860: [CMS-concurrent-reset-start]
2022-01-11T19:14:55.185-0800: 1.919: [CMS-concurrent-reset: 0.059/0.059 secs] [Times: user=0.10 sys=0.03, real=0.06 secs] 
2022-01-11T19:14:55.571-0800: 2.304: [GC (Allocation Failure) 2022-01-11T19:14:55.571-0800: 2.304: [ParNew: 153666K->13538K(157248K), 0.0272992 secs] 153666K->18672K(506816K), 0.0275117 secs] [Times: user=0.10 sys=0.02, real=0.02 secs] 
2022-01-11T19:14:56.965-0800: 3.698: [GC (Allocation Failure) 2022-01-11T19:14:56.965-0800: 3.698: [ParNew: 153314K->15291K(157248K), 0.0122546 secs] 158448K->26026K(506816K), 0.0127318 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
2022-01-11T19:14:57.683-0800: 4.416: [GC (Allocation Failure) 2022-01-11T19:14:57.683-0800: 4.416: [ParNew: 155067K->10713K(157248K), 0.0128050 secs] 165802K->30489K(506816K), 0.0129698 secs] [Times: user=0.06 sys=0.01, real=0.01 secs] 
Heap
 par new generation   total 157248K, used 49453K [0x00000005c0000000, 0x00000005caaa0000, 0x00000005e9990000)
  eden space 139776K,  27% used [0x00000005c0000000, 0x00000005c25d5010, 0x00000005c8880000)
  from space 17472K,  61% used [0x00000005c8880000, 0x00000005c92f6708, 0x00000005c9990000)
  to   space 17472K,   0% used [0x00000005c9990000, 0x00000005c9990000, 0x00000005caaa0000)
 concurrent mark-sweep generation total 349568K, used 19775K [0x00000005e9990000, 0x00000005feef0000, 0x00000007c0000000)
 Metaspace       used 35335K, capacity 36896K, committed 37220K, reserved 1081344K
  class space    used 4845K, capacity 5146K, committed 5220K, reserved 1048576K

G1日志

【停顿时间优先】

参数设置：-XX:+UseG1GC -Xloggc:g1-gc.log

理解G1日志格式：

https://blogs.oracle.com/poonam/understanding-g1-gc-logs
https://blog.gceasy.io/2016/07/07/understanding-g1-gc-log-format/ 这篇文章推荐读一下

grok 获取java日志 jvm gc日志开启_java_02

Java HotSpot(TM) 64-Bit Server VM (25.211-b12) for bsd-amd64 JRE (1.8.0_211-b12), built on Apr  1 2019 20:53:18 by "java_re" with gcc 4.2.1 (Based on Apple Inc. build 5658) (LLVM build 2336.11.00)
Memory: 4k page, physical 33554432k(714396k free)

/proc/meminfo:

CommandLine flags: -XX:-BytecodeVerificationLocal -XX:-BytecodeVerificationRemote -XX:InitialHeapSize=536870912 -XX:+ManagementServer -XX:MaxHeapSize=8589934592 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:TieredStopAtLevel=1 -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 
2022-01-11T19:17:51.920-0800: 1.361: [GC pause (G1 Evacuation Pause) (young), 0.0057847 secs]
   [Parallel Time: 3.4 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1361.7, Avg: 1361.8, Max: 1362.2, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 2.9, Diff: 2.9, Sum: 4.8]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [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.1, Max: 0.6, Diff: 0.6, Sum: 1.1]
      [Object Copy (ms): Min: 0.0, Avg: 1.9, Max: 2.4, Diff: 2.4, Sum: 15.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0]
         [Termination Attempts: Min: 1, Avg: 21.0, Max: 34, Diff: 33, Sum: 168]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 2.4, Avg: 2.8, Max: 2.9, Diff: 0.6, Sum: 22.4]
      [GC Worker End (ms): Min: 1364.6, Avg: 1364.6, Max: 1364.6, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 2.3 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.9 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 24.0M(24.0M)->0.0B(36.0M) Survivors: 0.0B->4096.0K Heap: 24.0M(512.0M)->3855.6K(512.0M)]
 [Times: user=0.02 sys=0.00, real=0.00 secs] 
2022-01-11T19:17:52.124-0800: 1.566: [GC pause (G1 Evacuation Pause) (young), 0.0076186 secs]
   [Parallel Time: 4.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1566.0, Avg: 1566.2, Max: 1566.6, Diff: 0.5]
      [Ext Root Scanning (ms): Min: 0.0, Avg: 0.4, Max: 1.4, Diff: 1.4, Sum: 3.3]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0]
      [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.1, Max: 0.5, Diff: 0.5, Sum: 0.7]
      [Object Copy (ms): Min: 1.9, Avg: 2.8, Max: 3.7, Diff: 1.8, Sum: 22.4]
      [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.7, Diff: 0.7, Sum: 4.7]
         [Termination Attempts: Min: 1, Avg: 23.2, Max: 45, Diff: 44, Sum: 186]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 3.5, Avg: 3.9, Max: 4.0, Diff: 0.5, Sum: 31.2]
      [GC Worker End (ms): Min: 1570.0, Avg: 1570.0, Max: 1570.1, Diff: 0.1]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.1 ms]
   [Other: 3.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 3.0 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.0 ms]
   [Eden: 36.0M(36.0M)->0.0B(300.0M) Survivors: 4096.0K->6144.0K Heap: 39.8M(512.0M)->8414.5K(512.0M)]
 [Times: user=0.03 sys=0.01, real=0.01 secs] 
2022-01-11T19:17:52.480-0800: 1.921: [GC pause (Metadata GC Threshold) (young) (initial-mark), 0.0117597 secs]
   [Parallel Time: 7.1 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 1921.2, Avg: 1921.5, Max: 1922.3, Diff: 1.1]
      [Ext Root Scanning (ms): Min: 1.6, Avg: 2.3, Max: 2.7, Diff: 1.1, Sum: 18.8]
      [Update RS (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 0.9]
         [Processed Buffers: Min: 0, Avg: 0.5, Max: 1, Diff: 1, Sum: 4]
      [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.2, Max: 0.7, Diff: 0.7, Sum: 1.6]
      [Object Copy (ms): Min: 3.3, Avg: 3.8, Max: 4.3, Diff: 1.0, Sum: 30.1]
      [Termination (ms): Min: 0.0, Avg: 0.3, Max: 0.4, Diff: 0.4, Sum: 2.5]
         [Termination Attempts: Min: 1, Avg: 1.1, Max: 2, Diff: 1, Sum: 9]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 5.9, Avg: 6.7, Max: 7.0, Diff: 1.1, Sum: 54.0]
      [GC Worker End (ms): Min: 1928.1, Avg: 1928.2, Max: 1928.3, Diff: 0.2]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 4.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 3.9 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 66.0M(300.0M)->0.0B(292.0M) Survivors: 6144.0K->14.0M Heap: 73.2M(512.0M)->15.5M(512.0M)]
 [Times: user=0.04 sys=0.01, real=0.01 secs] 
2022-01-11T19:17:52.492-0800: 1.933: [GC concurrent-root-region-scan-start]
2022-01-11T19:17:52.497-0800: 1.938: [GC concurrent-root-region-scan-end, 0.0051380 secs]
2022-01-11T19:17:52.497-0800: 1.938: [GC concurrent-mark-start]
2022-01-11T19:17:52.497-0800: 1.939: [GC concurrent-mark-end, 0.0005947 secs]
2022-01-11T19:17:52.497-0800: 1.939: [GC remark 2022-01-11T19:17:52.498-0800: 1.939: [Finalize Marking, 0.0007418 secs] 2022-01-11T19:17:52.498-0800: 1.940: [GC ref-proc, 0.0000878 secs] 2022-01-11T19:17:52.498-0800: 1.940: [Unloading, 0.0019575 secs], 0.0031669 secs]
 [Times: user=0.01 sys=0.00, real=0.01 secs] 
2022-01-11T19:17:52.501-0800: 1.942: [GC cleanup 17M->17M(512M), 0.0007957 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
2022-01-11T19:17:52.502-0800: 1.943: [GC concurrent-cleanup-start]
2022-01-11T19:17:52.502-0800: 1.943: [GC concurrent-cleanup-end, 0.0000174 secs]
2022-01-11T19:17:55.118-0800: 4.560: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0368034 secs]
   [Parallel Time: 23.9 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 4559.9, Avg: 4560.0, Max: 4560.0, Diff: 0.2]
      [Ext Root Scanning (ms): Min: 1.3, Avg: 1.7, Max: 2.2, Diff: 0.8, Sum: 13.3]
      [Update RS (ms): Min: 0.0, Avg: 0.4, Max: 2.2, Diff: 2.2, Sum: 2.9]
         [Processed Buffers: Min: 0, Avg: 0.6, Max: 2, Diff: 2, Sum: 5]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Code Root Scanning (ms): Min: 0.0, Avg: 1.0, Max: 2.8, Diff: 2.8, Sum: 8.3]
      [Object Copy (ms): Min: 18.5, Avg: 19.9, Max: 21.2, Diff: 2.7, Sum: 159.1]
      [Termination (ms): Min: 0.0, Avg: 0.7, Max: 0.9, Diff: 0.9, Sum: 5.3]
         [Termination Attempts: Min: 1, Avg: 12.1, Max: 23, Diff: 22, Sum: 97]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 23.4, Avg: 23.6, Max: 23.8, Diff: 0.4, Sum: 189.1]
      [GC Worker End (ms): Min: 4583.4, Avg: 4583.6, Max: 4583.7, Diff: 0.3]
   [Code Root Fixup: 0.2 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 12.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 11.0 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 1.0 ms]
   [Eden: 292.0M(292.0M)->0.0B(270.0M) Survivors: 14.0M->36.0M Heap: 307.3M(512.0M)->37.0M(512.0M)]
 [Times: user=0.09 sys=0.02, real=0.04 secs] 
2022-01-11T19:17:55.155-0800: 4.597: [GC concurrent-root-region-scan-start]
2022-01-11T19:17:55.168-0800: 4.610: [GC concurrent-root-region-scan-end, 0.0130025 secs]
2022-01-11T19:17:55.168-0800: 4.610: [GC concurrent-mark-start]
2022-01-11T19:17:55.169-0800: 4.610: [GC concurrent-mark-end, 0.0001416 secs]
2022-01-11T19:17:55.169-0800: 4.610: [GC remark 2022-01-11T19:17:55.169-0800: 4.610: [Finalize Marking, 0.0009400 secs] 2022-01-11T19:17:55.170-0800: 4.611: [GC ref-proc, 0.0001618 secs] 2022-01-11T19:17:55.170-0800: 4.612: [Unloading, 0.0028892 secs], 0.0044676 secs]
 [Times: user=0.02 sys=0.00, real=0.01 secs] 
2022-01-11T19:17:55.173-0800: 4.615: [GC cleanup 39M->39M(512M), 0.0006256 secs]
 [Times: user=0.01 sys=0.00, real=0.00 secs] 
Heap
 garbage-first heap   total 524288K, used 189423K [0x00000005c0000000, 0x00000005c0200800, 0x00000007c0000000)
  region size 2048K, 93 young (190464K), 18 survivors (36864K)
 Metaspace       used 35233K, capacity 36838K, committed 36992K, reserved 1081344K
  class space    used 4849K, capacity 5147K, committed 5248K, reserved 1048576K

grok 获取java日志 jvm gc日志开启_grok 获取java日志_03

Gc日志分析文件

在线gceasy

官网：https://gceasy.io

可以比较不同的垃圾收集器的吞吐量和停顿时间

比如打开cms-gc.log和g1-gc.log

pso-gc.log

-XX:+UseParallelGC

https://gceasy.ycrash.cn/my-gc-report.jsp?p=c2hhcmVkLzIwMjIvMDEvMTEvLS1wc28tZ2MubG9nLS0xMS0zMy00OQ==&channel=WEB

grok 获取java日志 jvm gc日志开启_sed_04

grok 获取java日志 jvm gc日志开启_jvm_05

cms-gc.log

https://gceasy.ycrash.cn/my-gc-report.jsp?p=c2hhcmVkLzIwMjIvMDEvMTEvLS1jbXMtZ2MubG9nLS0xMS0zMS01&channel=WEB

grok 获取java日志 jvm gc日志开启_Time_06

grok 获取java日志 jvm gc日志开启_java_07

g1-gc.log

https://gceasy.io/my-gc-report.jsp?p=c2hhcmVkLzIwMjIvMDEvMTEvLS1nMS1nYy5sb2ctLTExLTI2LTQ2&channel=WEB

内存占用

grok 获取java日志 jvm gc日志开启_java_08

停顿时间
[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-QY65q2Ji-1641904024739)(/Users/xuyy/Library/Application Support/typora-user-images/image-20220111192952507.png)]

离线GCviewer

下载，解压，idea打开。执行mvn clean install ，找到/target/gcviewer-1.36.jar 打开

链接: https://pan.baidu.com/s/1rA7HtR2g-MNwzogv3ZJqeQ 提取码: p6ca

grok 获取java日志 jvm gc日志开启_grok 获取java日志_09

G1调优和优化指南

一、是否选择使用G1

是否选用G1垃圾收集器的判断依据 jdk9默认G1

https://docs.oracle.com/javase/8/docs/technotes/guides/vm/G1.html#use_cases

50%以上的堆被存活对象占用
对象分配和晋升的速度变化非常大
垃圾回收时间比较长
适合大内存（6G以上，不要低于4g），多核

二、开启G1

使用G1GC垃圾收集器: -XX:+UseG1GC

修改配置参数，获取到gc日志，使用GCViewer分析吞吐量和响应时间

grok 获取java日志 jvm gc日志开启_grok 获取java日志_10

三、调优思路

1、试着增加内存

一般内存不够，第一反应是试着增加内存看看，要不断的去尝试，是很枯燥的

比如设置堆内存的大小，获取到gc日志，使用GCViewer分析吞吐量和响应时间

-XX:MetaspaceSize=100M 
-Xms300M 
-Xmx300M

grok 获取java日志 jvm gc日志开启_jvm_11

2、设置目标停顿时间

G1主打的就是可以自定义最大停顿时间,设置最大停顿时间，获取到gc日志，使用GCViewer分析吞吐量和响应时间

-XX:MaxGCPauseMillis=20 设置最大GC停顿时间指标

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-Y5cTxmw5-1641985840055)(/Users/xuyy/Library/Application Support/typora-user-images/image-20220112185827980.png)]

3、启动并发GC堆时内存占用百分比

-XX:InitiatingHeapOccupancyPercent=45 G1用它来触发并发GC周期,基于整个堆的使用率,而不只是某一代内存的 使用比例。值为 0 则表示“一直执行GC循环)'. 默认值为 45 (例如, 全部的 45% 或者使用了45%).

grok 获取java日志 jvm gc日志开启_java_12

四、最佳使用指南

官网建议

https://docs.oracle.com/javase/8/docs/technotes/guides/vm/gctuning/g1_gc_tuning.html#recommendations

1、不要手动设置新生代和老年代的大小，只要设置整个堆的大小

G1收集器在运行过程中，会自己调整新生代和老年代的大小

其实是通过adapt代的大小来调整对象晋升的速度和年龄，从而达到为收集器设置的暂停时间目标

如果手动设置了大小就意味着放弃了G1的自动调优

2、不断调优暂停时间目标

一般情况下这个值设置到100ms或者200ms都是可以的(不同情况下会不一样)，但如果设置成50ms就不太合理。暂停

时间设置的太短，就会导致出现G1跟不上垃圾产生的速度。最终退化成Full GC。所以对这个参数的调优是一个持续

的过程，逐步调整到最佳状态。暂停时间只是一个目标，并不能总是得到满足。

3、使用-XX:ConcGCThreads=n来增加标记线程的数量

IHOP如果阀值设置过高，可能会遇到转移失败的风险，比如对象进行转移时空间不足。如果阀值设置过低，就会使标

记周期运行过于频繁，并且有可能混合收集期回收不到空间。

IHOP值如果设置合理，但是在并发周期时间过长时，可以尝试增加并发线程数，调高ConcGCThreads。

4、MixedGC调优

-XX:InitiatingHeapOccupancyPercent    用于更改标记阈值。
-XX:G1MixedGCLiveThresholdPercent     用于更改混合垃圾收集决策。
-XX:G1MixedGCCountTarger   -XX:G1OldCSetRegionThresholdPercent 用于调整旧区域的 CSet。