记录一次JVM问题排查定位过程

问题现象描述

应用每隔一段时间会发生探活程序访问异常，导致项目自动重启（公司策略）

问题排查定位

初步怀疑应用访问量过大

解决方案：增加两个应用实例，发现问题依旧存在，接下来着重观察单台实例的运行情况（追踪应用内存、CPU等资源利用情况）

应用资源耗损情况追踪记录

备注：详细追踪记录不做描述，此处仅记录一下追踪过程以及方式方法

利用公司应用监控工具对应用运行情况进行观察（若没有工具则忽略）

这种途径对应用运行情况的监控仅能让我们从全局整体上了解应用的执行情况，要想进行更细的了解需要配合JVM调优工具进行堆栈日志分析等操作

JVM调优工具使用

1、首先定位java进程：jps命令

2、查看当前进程内线程的运行情况：top -Hp 进程ID

3、定位资源耗损异常的线程ID，将线程ID转换为16进制（因为堆栈日志中线程ID是16进制表示）

如下：10的16进制表示为0xa

4、打印堆栈日志：jstack命令

主要用于分析线程运行调度的问题，是否发生死锁、等待、阻塞等异常现象，详情请见：https://www.cnblogs.com/snake23/archive/2019/01/28/10329149.html

5、导出堆转储日志dump文件：jmap命令

主要用于分析堆内存中对象，详情请见：https://www.cnblogs.com/duanxz/archive/2012/07/10/2584249.html

==============================================================================================================================================================

案例：本文主要分析一个频繁GC (Allocation Failure)的case

症状：在一天的时间内，发生了5000多次gc，其中full gc为4次，平均将近200毫秒，大部分是young gc(allocation failure为主)，平均15毫秒左右，且survivor区使用率很低。

JVM参数：

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/data/logs/activity-deliver/heapdump.hprof -XX:InitialHeapSize=4294967296 -XX:MaxHeapSize=4294967296 -XX:NewRatio=3 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:SurvivorRatio=8 -XX:-UseAdaptiveSizePolicy -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseParallelGC

JDK版本：

java version "1.8.0_191"
Java(TM) SE Runtime Environment (build 1.8.0_191-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.191-b12, mixed mode)

full gc日志：

2021-09-29T15:40:57.118+0800: 1.912: [GC (Metadata GC Threshold) [PSYoungGen: 671750K->20724K(944128K)] 671750K->20748K(4089856K), 0.0583319 secs] [Times: user=0.07 sys=0.02, real=0.06 secs] 
2021-09-29T15:40:57.177+0800: 1.970: [Full GC (Metadata GC Threshold) [PSYoungGen: 20724K->0K(944128K)] [ParOldGen: 24K->20314K(3145728K)] 20748K->20314K(4089856K), [Metaspace: 20526K->20513K(1067008K)], 0.0748956 secs] [Times: user=0.23 sys=0.02, real=0.07 secs] 
2021-09-29T15:40:58.524+0800: 3.318: [GC (Metadata GC Threshold) [PSYoungGen: 748439K->23842K(944128K)] 768754K->44228K(4089856K), 0.0675022 secs] [Times: user=0.09 sys=0.03, real=0.07 secs] 
2021-09-29T15:40:58.592+0800: 3.385: [Full GC (Metadata GC Threshold) [PSYoungGen: 23842K->0K(944128K)] [ParOldGen: 20386K->29991K(3145728K)] 44228K->29991K(4089856K), [Metaspace: 34293K->34293K(1079296K)], 0.0783246 secs] [Times: user=0.23 sys=0.00, real=0.08 secs] 
2021-09-29T15:40:59.813+0800: 4.607: [GC (Allocation Failure) [PSYoungGen: 839680K->34578K(944128K)] 869671K->64577K(4089856K), 0.0815178 secs] [Times: user=0.10 sys=0.01, real=0.09 secs] 
2021-09-29T15:41:00.242+0800: 5.035: [GC (Allocation Failure) [PSYoungGen: 874258K->12176K(944128K)] 904257K->42183K(4089856K), 0.0230919 secs] [Times: user=0.08 sys=0.01, real=0.03 secs] 
2021-09-29T15:41:01.664+0800: 6.457: [GC (Allocation Failure) [PSYoungGen: 851856K->26106K(944128K)] 881863K->56121K(4089856K), 0.0533749 secs] [Times: user=0.11 sys=0.00, real=0.06 secs] 
2021-09-29T15:41:03.817+0800: 8.611: [GC (Metadata GC Threshold) [PSYoungGen: 654660K->30115K(944128K)] 684675K->60138K(4089856K), 0.0528778 secs] [Times: user=0.10 sys=0.02, real=0.05 secs] 
2021-09-29T15:41:03.870+0800: 8.664: [Full GC (Metadata GC Threshold) [PSYoungGen: 30115K->0K(944128K)] [ParOldGen: 30023K->39881K(3145728K)] 60138K->39881K(4089856K), [Metaspace: 57034K->57034K(1101824K)], 0.1776656 secs] [Times: user=0.53 sys=0.01, real=0.18 secs] 
2021-09-29T15:41:06.758+0800: 11.551: [GC (Allocation Failure) [PSYoungGen: 839680K->25668K(944128K)] 879561K->65557K(4089856K), 0.0459025 secs] [Times: user=0.07 sys=0.01, real=0.04 secs] 
2021-09-29T15:41:08.221+0800: 13.014: [GC (Allocation Failure) [PSYoungGen: 865348K->28854K(944128K)] 905237K->68751K(4089856K), 0.0304194 secs] [Times: user=0.10 sys=0.01, real=0.03 secs] 
2021-09-29T15:41:09.745+0800: 14.538: [GC (Allocation Failure) [PSYoungGen: 868534K->36508K(944128K)] 908431K->76414K(4089856K), 0.0338516 secs] [Times: user=0.11 sys=0.00, real=0.03 secs] 
2021-09-29T15:41:11.933+0800: 16.726: [GC (Allocation Failure) [PSYoungGen: 876188K->61222K(944128K)] 916094K->101136K(4089856K), 0.0901583 secs] [Times: user=0.28 sys=0.02, real=0.09 secs] 
2021-09-29T15:41:13.993+0800: 18.786: [GC (Metadata GC Threshold) [PSYoungGen: 714430K->74390K(944128K)] 754343K->114312K(4089856K), 0.0923356 secs] [Times: user=0.21 sys=0.02, real=0.10 secs] 
2021-09-29T15:41:14.086+0800: 18.879: [Full GC (Metadata GC Threshold) [PSYoungGen: 74390K->0K(944128K)] [ParOldGen: 39921K->98430K(3145728K)] 114312K->98430K(4089856K), [Metaspace: 93057K->92497K(1136640K)], 0.3281080 secs] [Times: user=0.92 sys=0.05, real=0.32 secs]

从日志可以发现：发生的4次full gc，都是由于Metadata GC Threshold造成的，且引发一次minor gc

Full GC (Metadata GC Threshold)

 

这里使用的是java8，参数没有明确指定metaspace的大小和上限，查看一下

sh-4.2# jstat -gcmetacapacity 10
   MCMN       MCMX        MC       CCSMN      CCSMX       CCSC     YGC   FGC    FGCT     GCT   
   0.0      1177600.0   144984.0    0.0      1048576.0   16984.0  5068     4    0.659   60.208

可以看到MCMX(Maximum metaspace capacity (kB))有一个多G，而MC(Metaspace capacity (kB))才100多M左右，为啥会引起Full GC (Metadata GC Threshold)

相关参数

  • -XX:MetaspaceSize，初始空间大小(也是初始的阈值，即初始的high-water-mark)，达到该值就会触发垃圾收集进行类型卸载，同时GC会对该值进行调整：如果释放了大量的空间，就适当降低该值；如果释放了很少的空间，那么在不超过MaxMetaspaceSize时，适当提高该值。
  • -XX:MaxMetaspaceSize，最大空间，默认是没有限制的，取决于本地系统空间容量。
  • -XX:MinMetaspaceFreeRatio，在GC之后，最小的Metaspace剩余空间容量的百分比(即元数据在当前分配大小的最大占用大小)，如果空闲比小于这个参数(即超过了最大占用大小)，那么将对meta space进行扩容。
  • -XX:MaxMetaspaceFreeRatio，在GC之后，最大的Metaspace剩余空间容量的百分比(即元数据在当前分配大小的最小占用大小)，如果空闲比大于这个参数(即小于最小占用大小)，那么将对meta space进行缩容.

由于没有设置，在机器上的默认值为：

sh-4.2# java -XX:+PrintFlagsFinal | grep Meta
    uintx InitialBootClassLoaderMetaspaceSize       = 4194304                             {product}
    uintx MaxMetaspaceExpansion                     = 5451776                             {product}
    uintx MaxMetaspaceFreeRatio                     = 70                                  {product}
    uintx MaxMetaspaceSize                          = 18446744073709547520                {product}
    uintx MetaspaceSize                             = 21807104                            {pd product}
    uintx MinMetaspaceExpansion                     = 339968                              {product}
    uintx MinMetaspaceFreeRatio                     = 40                                  {product}
     bool TraceMetadataHumongousAllocation          = false                               {product}
     bool UseLargePagesInMetaspace                  = false                               {product}

可以看到MinMetaspaceFreeRatio为40，MaxMetaspaceFreeRatio为70，MetaspaceSize为20M，Full GC (Metadata GC Threshold)主要分为了四次

Metaspace: 20526K->20513K(1067008K)

Metaspace: 34293K->34293K(1079296K)

Metaspace: 57034K->57034K(1101824K)
Metaspace: 93057K->92497K(1136640K)

可以看到metaspace的阈值不断动态调整，只要没有超过Max值就没有致命影响，但是对于低延时的应用来讲，是要尽量避免动态调整引起的gc耗时，可以根据调优计算并设置初始阈值来解决。

GC (Allocation Failure)

分析完full gc之后我们看下young gc，看log里头99%都是GC (Allocation Failure)造成的young gc。Allocation Failure表示向young generation(eden)给新对象申请空间，但是young generation(eden)剩余的合适空间不够所需的大小导致的minor gc。

【推广】 免费学中医，健康全家人
原文地址：https://www.cnblogs.com/wly1-6/p/15328806.html