JVM GC排查-JFR
现象：
2024-09-12日发现某api服务GC告警明显增多
从告警上看，不仅GC次数有明显变多，更严重的是GC耗时很长，并且都是FullGC。
分析：
从告警上看，现象就是FullGC，先找一台机器（xx.xx.13.141）看看，在15:37和16:06分别有一次FullGC告警，看一下15:37的GC日志，确实发生了一次1.05s的FullGC
为什么会发生FullGC？一定是Old区内存都不够了，继续查看这次GC之前的日志（如下图），可以看到在Concurrent Cycles期间因为 humongous object的原因内存一直在涨，最终内存不足，导致FullGC。
继续查看这个时间点早一点的日志（下图）也能发现Concurrent Cycles也是因为humongous object分配导致。
因为G1的MixGC不会一次回收所有垃圾，而是会进行多次MixGC回收垃圾直到垃圾占比小于阈值（5%），如果某个时间段大对象分配频繁，就会发生MixGC跟不上分配节奏导致内存耗尽。
我们初步判断是因为大对象导致本次FullGC，dump内存看看大对象是什么？（RegionSize=2M，超过1M就是大对象）
从图上可以看出大对象基本分为两类：
第一类：
通过RequestMapping OkHttpClient关键词能搜到对应代码如下，就是一个http请求的拦截器打印日志
第二类：
看起来像Json，仔细看又不太像，因为这个字符串内有class的名称，一般json是没有className的，但是我们仍然基本能确定是跟Customer对象相关的。
我们现在已经确定了这些大对象都是 byte[], char[] 数组，但是怎么确定这些对象是因为哪行代码分配的呢？我们可以关闭日志打印，但是治标不治本，必须弄清楚这些大对象是否合理，如果不知道相关的代码我们没办法进一步排查和修复。
这里给出3种可以尝试的方式：
- 关键词搜代码：通过字符串内的特殊片段结合项目的业务去搜索和猜测相关代码，如果对项目的业务熟悉这种方式也很快能找到对应代码。
- dragonwell：是alibaba的一款JVM，这个JVM有一个增强的功能，对于基本数据类型的大数组分配，可以打印分配的堆栈，这样我们能准确的找到对应的代码。见 阿里巴巴Dragonwell8用户指南
- 通过JFR观察 outside 的TLAB分配记录
知识加油站：什么是TLAB？
我们知道堆内存是所有线程共享的，如果在堆上分配内存需要加锁。
为了提高性能，JVM会给每个线程单独分配一块自己的内存，这块内存就叫TLAB，线程分配对象时用自己的TLAB不需要加锁，当TLAB不够时，去堆再申请一块TLAB（要加锁）。
假设下面的场景，TLAB=100kb，已经使用90kb，如果要分配对象11kb，那么这时候怎么办？
很明显TLAB剩下的10kb不足以分配给11kb的对象，如果重新申请一个新的TLAB，那么就会导致10kb的空间浪费，为了平衡性能和空间浪费，JVM有一个TLAB最大浪费阈值（refill waste），10kb > refill waste就不会申请新的TLAB，而是11kb的对象直接在堆上分配，如果 10kb < refill waste，那么就会申请一块新的TLAB，10kb就浪费掉。
在JFR中可以持续观察TLAB的分配情况，Allocation in new TLAB表示在TLAB中分配，Allocation outside TLAB表示在TLAB外分配。
JFR如何使用？大家自行搜索
因为我们要找的对象是大对象，我们知道G1中大对象是在H区直接分配的，不可能使用TLAB，因此我们通过JFR查看Allocation outside TLAB事件大概就能知道大对象分配时的堆栈了。
先使用jcms命令收集JFR信息：maxage：保留多长时间的，maxsize：文件大小
jcmd pid JFR.start name=1.jfr maxage=1h maxsize=400MB使用JDK Mission Control工具（JDK自带）打开jfr文件，打开事件浏览器，找到Allocation outside TLAB，选中一个大对象查看堆栈
具体的堆栈如下：
简单梳理一下调用链路：
ShopCloseController.checkCloseShop
-> StockService.getStock
-> StockService.removeVirtualGoods
-> PssService.getVirtualGoods()
-> ApiResponse com.sun.proxy.$Proxy369.getChannelMihomeGoodsMap(Integer)
-> 日志打印
对应的源代码如下：
也就是说 getChannelMihomeGoodsMap 方法返回值太大了，我们自定义的OkHttp拦截器打印日志就造成了大对象。
拿一个具体的大字符串看看长什么样：看起来是这个接口返回了所有渠道的所有sku信息，这个字符串非常大，另外在打印日志时底层的StringBuilder又扩容导致最后的char[]非常巨大。
实际上我们并不需要所有渠道的sku，只需要一个渠道的sku即可，因此后续要替换接口。
对于第二种1M左右的大对象，从堆栈上很容易看到是 CustomerController.getDetail(long, int) 方法查了缓存，缓存查出来的就是byte[]（后怕：redis缓存在么大的key，也不怕把redis搞死）
通过源码也能看到，和上面的堆栈一致。
也就是说Customer对象序列化的byte[]数组太大了，虽然下图的字符串不完整，但是我们也能大概猜到是因为Customer的address太多导致，从图中能看到这个用户的id，
数据库查一下这个用户的地址有1501个，确实是地址太多了。
实际上从JFR上看，大对象不仅仅是上面这两种，还有因 InvoiceController.getList 底层返回数据多导致的大对象和 BranchCompanyController.list 缓存大导致的大对象，这里就不一一分析了。
总结
整体思路：
（1）为什么会GC？通过gc日志发现是大对象频繁分配导致
（2）大对象是什么？通过jmap dump内存后查看发现是日志打印的string等
（3）怎么修复？需要确定大对象从哪分配
（4）大对象在哪分配？通过JFR查看大对象分配时的堆栈，找到对应代码
（5）怎么修复？接口返回的数据减少不必要的数据
实际上从今年开始，我主导组内所有项目的GC治理开始，就发现了大对象是一个普遍现象，根本原因有二：
- 协议缺陷：服务之间调用使用http协议，参数和返回值都是string，一旦某些接口数据量大，必然会导致大的string对象，从现象来看都是某个对象有一些集合字段，集合太大，json序列化后的string就很大，二进制的序列化就不会有这个问题。
- 意思薄弱：开发人员在性能方面的意识非常薄弱，只管实现功能，至于性能怎么样压根不关心，以至于今年我在做GC分享的时候，有个leader问我你gc耗时30ms，我服务gc耗时1s还不是照样跑得好好的这样的问题。另外对于批量接口压根就不做数量的限制，基本都是全量数据直接扔出去。
