由于一些业务的接入层对延迟比较敏感，请求会偶尔发生超时失败。为了提升请求的成功率，决定对这一情况进行优化。经过一系列排查（排除数据库请求耗时等因素，通过毛刺监控和 FULL GC的时间重叠）发现是 FULL GC 导致的。

为了能看到更多信息，加入参数打印 GC 日志：

-XX:+PrintGCDateStamps  -XX:+PrintGC  -XX:+PrintGCDetails  -XX:+PrintHeapAtGC  -Xloggc:/usr/local/app/gc.log  -XX:+PrintGCApplicationStoppedTime  -XX:+PrintTenuringDistribution

然后重启服务。从 GC 日志中发现启动的时候会出现 Full GC，这里主要是元空间满了需要额外申请导致的。

2023-01-24T16:17:42.064+0800: 2.088: [Full GC (Metadata GC Threshold) [PSYoungGen: 9412K->0K(3670016K)] [ParOldGen: 88K->9081K(2097152K)] 9500K->9081K(5767168K), [Metaspace: 20535K->20534K(1067008K)], 0.0290137 secs] [Times: user=0.12 sys=0.01, real=0.03 secs] 
2023-01-24T16:17:43.445+0800: 3.469: [Full GC (Metadata GC Threshold) [PSYoungGen: 22108K->0K(3670016K)] [ParOldGen: 9089K->28976K(2097152K)] 31198K->28976K(5767168K), [Metaspace: 33900K->33900K(1079296K)], 0.1359828 secs] [Times: user=0.78 sys=0.04, real=0.14 secs] 
2023-01-24T16:17:46.198+0800: 6.222: [Full GC (Metadata GC Threshold) [PSYoungGen: 23285K->0K(3670016K)] [ParOldGen: 28984K->49499K(2097152K)] 52270K->49499K(5767168K), [Metaspace: 56353K->56353K(1099776K)], 0.1531985 secs] [Times: user=0.59 sys=0.01, real=0.15 secs] 
2023-01-24T16:17:54.701+0800: 14.725: [Full GC (Metadata GC Threshold) [PSYoungGen: 46050K->0K(3670016K)] [ParOldGen: 49523K->91041K(2097152K)] 95573K->91041K(5767168K), [Metaspace: 94423K->94423K(1134592K)], 0.2035744 secs] [Times: user=0.87 sys=0.05, real=0.20 secs]

当然如果日志不直观的话也可以把GC日志直接丢进去 https://gceasy.ycrash.cn/ 中进行分析

由于服务启动时会加载大量的类，但是运行时并不会有大量类加载和卸载，这边把 Metadata 设置的小一些也没有问题。

经过查找资料，元空间在 64 位服务端默认值为 20.75MB，达到这个值后 Full GC 会被触发卸载没用的类，然后这个高水位线将会重置，新的高水位线的值取决于 GC 后释放了多少元空间。如果释放的空间不足则会多次进行 Full GC 调整，为了避免频繁 GC，建议将 -XX:MetaspaceSize 设置为一个相对较高的值。

这边增加 jvm 参数：-XX:MetaspaceSize=300m -XX:MaxMetaspaceSize=1024m

效果：在首次扩容后就无 Full GC 了，第一次 Full GC 占用的耗时可以接受。

2023-02-02T05:30:29.730+0800: 5.042: [Full GC (Metadata GC Threshold) [PSYoungGen: 36760K->0K(3670016K)] [ParOldGen: 112K->36376K(2097152K)] 36872K->36376K(5767168K), [Metaspace: 48588K->48586K(1572864K)], 0.1238906 secs] [Times: user=0.57 sys=0.03, real=0.12 secs]

问题又发现

在运行一段时间后发现仍然有 Full GC，考虑到服务是无状态的，不会有长期留存在内存的数据，理论上Full GC 出现频率应该非常低，甚至不会出现 Full GC。

cat gc.log |grep Full
2023-01-24T00:33:36.686+0800: 114616.769: [Full GC (Ergonomics) [PSYoungGen: 23131K->0K(4166144K)] [ParOldGen: 2095268K->474135K(2097152K)] 2118399K->474135K(6263296K), [Metaspace: 128170K->128170K(1167360K)], 0.2923764 secs] [Times: user=1.69 sys=0.00, real=0.29 secs]
2023-01-24T01:59:33.224+0800: 144973.307: [Full GC (Ergonomics) [PSYoungGen: 58440K->0K(4130816K)] [ParOldGen: 2094093K->
477119K(2097152K)] 2152533K->477119K(6227968K), [Metaspace: 128291K->128291K(1167360K)], 0.3218960 secs] [Times: user=1.8
8 sys=0.00, real=0.32 secs]

可以看从晚上 12 点到 1 点，发生了两次 Full GC，线程平均被暂停了 300ms。

下载 arthas 进行对堆内存进行观察

curl -O https://arthas.aliyun.com/arthas-boot.jar
java -jar arthas-boot.jar
dashboard

经过一段时间观察，发现老年代内存缓慢上涨。接下来看一下到底是哪些对象占用的内存。

jmap -histo pid | head -n20

jmap -histo 3248481 | head -n20
 num     #instances         #bytes  class name
----------------------------------------------
   1:       7149743      706632272  [C
   2:       8587414      343496560  java.util.LinkedHashMap$Entry
   3:       8326319      266442208  nl.basjes.parse.useragent.AgentField$ImmutableAgentField
   4:        873292      165081888  [I
   5:       6552097      157250328  java.lang.String
   6:        457654      136150704  [B
   7:        745753      135005512  [Ljava.lang.Object;
   8:        573466       77016008  [Ljava.util.HashMap$Node;
   9:         81044       49715216  [Ljava.lang.String;
  10:         52683       38810288  [J
    11:        532928       29843968  java.util.LinkedHashMap
  12:        572761       18328352  nl.basjes.shaded.org.antlr.v4.runtime.atn.ATNConfig
  13:        333225       13329000  nl.basjes.parse.useragent.UserAgent$ImmutableUserAgent
  14:        538926       12934224  java.util.ArrayList
  15:        335487       10735584  java.util.Collections$UnmodifiableMap
  16:        285638        9140416  java.util.HashMap$Node
  17:        340348        8168352  java.util.Collections$UnmodifiableRandomAccessList

很直观的看到存在大量 Entry和第三方库中的 ImmutableAgentField，大概就能猜到用的第三方库中有一个 LinkedHashMap<xxx, ImmutableAgentField> 缓存，所以我们到第三方源码库中去找。

假如这里无法一眼看出问题，则需要 dump 内存下来，放到MAT中进行分析。

jmap -dump:format=b,file=dump.hprof pid

然后在 MAT 上配置 window–>Preferences–>memory Analuzer–>勾选keep unreachable objects–>apply and close。当堆过大的时候需要去调整 MAT 的堆大小。

这里由于能一眼看出来就不展开分析了。

源码定位

这边只有一处用到了 useragent 解析的库，所以比较好定位问题。

 private static final UserAgentAnalyzer userAgentAnalyzer = UserAgentAnalyzer
            .newBuilder()
            .hideMatcherLoadStats()
            .withCache(SIZE)
            .build();

通过跟踪源码，发现配置了缓存，往下跟，看一下缓存用在了哪里。

@DefaultSerializer(AbstractUserAgentAnalyzer.KryoSerializer.class)
public class AbstractUserAgentAnalyzer extends AbstractUserAgentAnalyzerDirect implements Serializable {
    public static final int DEFAULT_PARSE_CACHE_SIZE = 10000;
    protected int cacheSize = 10000;
    private transient Map<String, ImmutableUserAgent> parseCache;
}

public static class ImmutableUserAgent implements UserAgent {
        private final String userAgentString;
        private final ImmutableAgentField userAgentStringField;
        private final Map<String, ImmutableAgentField> allFields;
}

可以看到类使用了一个 Map<String, ImmutableUserAgent> 作缓存，ImmutableUserAgent 的 allFields 是使用 Map<String, ImmutableAgentField> 表示的，但是其实字段都是固定的，这样写会创建大量没有意义的 Entry 节点，这个库这样处理其实不太好，不过这也和上面的堆内存分析对上了。

解决方案有三个，

减小缓存，让缓存能在几次垃圾回收的时候就被填满，在 Eden 区域被收集走。
增大老年代，并且同时增大缓存，使得全部数据都能放到老年代中。
直接关闭缓存

为了确定哪个方案比较好，我们需要继续跟进源码确定缓存中的 key 存储的是啥内容，以确定命中率如何。

    @Override
    public ImmutableUserAgent parse(MutableUserAgent userAgent) {
        if (userAgent == null) {
            return null;
        }
        if (parseCache == null) {
            userAgent.reset();
            return super.parse(userAgent);
        }

        String userAgentString = userAgent.getUserAgentString();
        ImmutableUserAgent cachedValue     = parseCache.get(userAgentString);
        if (cachedValue != null) {
            return cachedValue; // As it is immutable it can safely be returned as is
        } else {
            cachedValue = super.parse(userAgent);
            parseCache.put(userAgentString, cachedValue);
        }
        // We have our answer.
        return cachedValue;
    }

可以看到这里的 key 是 User-Agent，基本上很少会重复，所以这里缓存命中率极低，这边选择直接关闭缓存。

关闭这里的缓存后再次上线一段时间观察效果。

最终效果

经过一天的请求，再次打开 dashboard，可以看到 Full GC 只在启动的时候执行了一次，问题得到解决。

cat gc.log |grep Full
[Full GC (Metadata GC Threshold) [PSYoungGen: 36691K->0K(3670016K)] [ParOldGen: 120K
->36362K(2097152K)] 36811K->36362K(5767168K), [Metaspace: 48585K->48583K(1572864K)], 0.1127735 secs] [Times: user=0.43 sy
s=0.04, real=0.11 secs]