暑期进行的开学季大扫除活动，制定了详细的项目资源巡查和保障制度。随着9月份开学季到来，点单业务迎来又一高峰，每日资源巡检做为预警手段已成为常态。开学季期间，志文还通过资源巡检提前察觉到uf4c-ap项目潜在危险，为我们在午高峰前争取了充裕的处理时间。 无疑，资源巡检是我们保障项目稳定性的一大利器。
自发现uf4b-app服务Full GC，到本文完成共历时近一个月。本文对uf4b-app频繁Full GC现象的排查过程、具体原因以及改进计划进行了分析与梳理。
1.异常现象
1.1Full GC初现
在某天接近午高峰进行uf4b-app项目的巡检时，hera显示在近30分钟内项目发生了一次Full GC。于是点进4个pod逐个检查，发现各项资源情况(cpu、内存、耗时)都比较稳定，接口请求也没有异常报错的情况。发生Full GC的pod，堆内存中的Old Gen由170M降到120M左右，耗时约430ms。
下图为 2023-09-13 11:20 ~ 11:30 的hera数据：
uf4b-app整体数据一览：稳如老狗
单个pod情况
接口一览
至此，我认为项目整体是正常的，发生Full GC原因可能有两点：
- uf4b-app项目没有弹性扩缩容量的机制，无法通过定期扩缩容重置pod，故随着时间推移，存在一些 “大对象/老对象” 堆积。
- 随着中午流量的增多，内存开销增大，于是启动Full GC进行一次清理。
基于以上两点原因，我并不认为Full GC是什么大问题，毕竟项目指标都很稳。不过我也并没有掉以轻心，Full GC虽然谈不上令人闻之色变，但我们也要给予足够的重视。至此，我留了个心眼，打算后面的巡检每天都重点照顾一下uf4b-app。
1.2 疑点重重
虽然uf4b-app看起来确实没有什么问题，但是心中仍然存在一些疑惑，此前分析的两点可能的原因好像并不能解释完全。疑问点：
代码是否存在内存泄漏
按理来说，即使符合此前分析的两点原因，那也说明代码里出现了可能的内存泄漏，只有这样才会导致每次Young GC后，会往老年代里面放入一些存活年龄较大的对象。
Full GC的执行策略不符合预期
uf4b-app分配了1.5G的JVM内存空间，与其他项目一致，使用默认的JVM配置和G1回收策略。按照默认设置，也要在Old Gen占用整个堆45%(此处有误。当时我以为是这个比例，后面深入了解后发现G1是在该阈值触发MixedGC流程)时才会触发Full GC。以这个比例计算，应该在1536*0.45=537.6M时触发，此触发条件与预期不符。并且在Full GC时，为何只能清理50M的内存，也太少了。
带着这两个疑点，又进入了排查。
内存泄漏检查
常见的可能导致内存泄漏的场景和情况：
- ThreadLocal长期存储大对象，长时间不清理项目中仅使用ThreadLocal存储当前线程的用户信息，并无造成内存泄漏的风险。
- 匿名内部类和非静态内部类引用了外部类的实例，这个引用会导致外部类的实例无法被垃圾回收在我们的开发规范中，通常采用失血模型，即数据与逻辑分离，内部类引用外部类实例造成的无法垃圾回收情况。
- 未关闭流资源项目中仅使用
ByteArrayInputStream和ByteArrayOutputStream这两个流，在源代码中，这两个流并不需要关闭。源码如下：
/**
* Closing a <tt>ByteArrayOutputStream</tt> has no effect. The methods in
* this class can be called after the stream has been closed without
* generating an <tt>IOException</tt>.
*/
public void close() throws IOException {
}Full GC的执行策略
在后面几天的排查中，对uf4b-app服务一周的数据进行总览发现，Full GC并不是个例。几乎每个pod一天都要Full GC 1～2次，并且发生时间和条件并不规律。有时候老年代刚过100M就进行Full GC，有时候老年代达到250M才进行Full GC。G1回收器的设计初衷就是通过YoungGc和MixedGC来避免FullGC，多次FullGC是很不合理的。
还发现了一个特殊现象，uf4b-app发布后的第二天早晨，有pod就进行了一次Full GC。此处老年代由138.5M → 106.5M，清理了个寂寞？早晨并非业务高峰期，中间间隔不到10小时。
这些现象完全推翻了此前的两个猜想。若是内存泄漏，不可能在半夜低峰期就积攒如此多的老对象。其次若是内存若是随着业务流量的增长而增加，那么Full GC的时间分布应该有规律可循。
这里我隐约有了些想法，可能Full GC是由某些调用触发的，某些接口可能占用了大量服务资源呢？可是观察Full GC时间段接口请求记录，并未发现有超时或者ERROR，无法定位到是哪个接口出了问题。所以这个猜想暂且保留，不一定是接口调用原因。
2.深入排查
带着万分迷惑，我决定换一个思路，既然uf4b-app本身看不出问题，那就看看其他服务是否有类似的情况。
2.1 横向对比
由于大部分服务都是有扩缩容的，所以这些服务几乎没有Full GC，也没法构成参考作用。在hera上找了好一会，终于发现data-report是没有扩缩容的，点进去看了看，没想到竟有些意外之喜(跟本次排查思路没有关系，但跟本次排查结论又有点关系。到底有没有关系？如有)。
data-report某个pod在14号晚上9点左右，伴随着疯狂的youngGC，老年代内存飙升。从现象上来说，youngGC后年轻代存活的对象进入老年代，这个是完全合理的。但关键问题在于，这个时间段并没有执行刷数据的任务。跟彦棨再三确认过，data-report刷数据是13号晚上做的，14号晚上没有定时任务，也没有手动任务。此处的内存激增总归是个异常现象，彦棨对data-report最为熟悉，这个异常让彦棨去进行排查了。
2.2 火焰图
想到上次晨光在uf4c-app排查时候导出了火焰图，可以看到CPU资源和内存情况，并且通过该方法精确定位到了死循环的方法，那么我也来试试。由于火焰图只能导出实时的，没办法拿到Full GC那个时刻的资源情况。这里便采用守株待兔的方式，hera页面打开等着，等到出现一个Full GC的时候，迅速导出火焰图查看资源情况。
通过搜索“wosai”关键词，可以看到具体的资源占用情况。如图，紫色为wosai相关的方法。从这个导出火焰图的表现来，执行方法都是正常的，并不存在资源错误占用的情况。严谨起见，过了几分钟我又导出了一次。后面这次导出火焰图，资源占用分配与第一次不一致，这也是正常的，毕竟不同时刻服务内部执行方法都不相同。总的来看，火焰图体现的服务资源情况无任何异常。
比较可惜，火焰图展示的数据是已经Full GC过后的，GC后也并未有什么没能释放的线程或者内存。所以火焰图这条线索也无法进一步挖掘了。（ps：什么时候我们公司可以接入阿里开源工具Arthas，实时监控内存、gc、线程的状态信息）
2.3初窥门径
接近一周过去了，异常排查仍旧没有头绪。周末下午一边写周报一边盯着hera，想着能不能有机会发现点啥子，让我充填一下周报的内容。好巧不巧，还真有。
在 2023-09-17 16:13 ~ 16:14 时，发现某个pod发生了一次FullGC。这次照常浏览了一下接口请求，发现在这一分钟内，发现有两个耗时较长的接口请求均只请求了一次。一个是创建商品，一个是导出群接龙订单Excel。如果按照之前的粗略推断，FullGC由某个调用引起，那肯定不能是创建商品。心中突然一激灵，该不会是导出群接龙订单吧！？
紧接着赶紧去阿里云sls查询这个条导出群接龙订单的请求日志。阿里云这边日志的时间和我们hera上的时候略有偏差，hera大概有1分钟左右的延迟。但是好在这段时间内，导出群接龙订单的请求只有这一个，毫无疑问就是这条日志记录。比对pod_name，好家伙，处理这个请求的pod正是发生FullGC的pod。（-28zs9抱拳：正是在下）
当然，不能凭空冤枉群接龙。刚好日志打印了返回值，返回了excel下载地址。将excel下载下来，看看excel有多大的数据量把项目搞得FullGC了。但是结果出乎意料，整个excel一同7条数据，大小不到15k。uf4b-app的1.5G分配内存被这个小小15k的excel搞的FullGC，难以置信。可能群接龙不一定是罪魁祸首。
这里群接龙的冤屈洗刷了一半，但是到手的线索又不忍心丢了。顺着刚才的思路，我去挨个查看了以前FullGC那一分钟的调用是否有群接龙导出，以及请求的pod是否与GC的pod为同一个。
随机抽查了几个FullGC，果不其然，伴随着FullGC的一定是群接龙的调用！但是，excel文件仍旧是小的可怜。不过更大的进展是，可以肯定群接龙和FullGC是挂钩的。一周的FullGC次数和群接龙订单导出调用次数相同，发生时间也一致！
再回过头来看，第一次排查时，粗粒度的时间妄图找到这个罪魁祸首无异于大海捞针。若不是这次巧合，可能需要更久的时间才能将之挖掘出来。
接口一览（谁是卧底？）
3.成因分析
经过一些列的排查，取得了阶段性的战果：群接龙导出与FullGC的强关联。但是，为何小小的excel文件会让服务FullGC呢？其他服务也有excel相关的功能，甚至能达到上万条数据的导入导出，并没见到这种现象。FullGC产生的真正原因仍旧在迷雾之中，等待揭晓。这就像柯南中，猜到凶手是谁了，却不知道作案细节，就缺了那“临门一针”。
3.1 循序渐进
为了弥补那临门一针，我开始恶补G1垃圾收集器相关的知识，希望能找到一些理论依据。如下是归纳后的一些核心知识点。
G1简介
G1最大的特点就是非常重视高吞吐量与软实时性(soft real-time，稍微超出几次最后期限也没有什么问题的系统，例如网络银行系统)的最佳平衡，它允许用户来设定期望最大暂停时间(Stop the word)。
G1垃圾收集器可以预测下次 GC 会导致应用程序暂停多长时间。根据预测出的结果，G1会通过延迟执行GC、拆分 GC 目标对象等手段来尽量满足用户设置的期望最大暂停时间，默认的暂停目标是 200ms。当然，你想让GC时暂停多久，它就能尽量的满足你。
G1内存划分
G1中划分为年轻代(young generation，红色区域)、老年代(old generation，蓝色区域)、空闲区(free regions，灰色区域)以及大对象(Humongous Region，蓝色带H区域)。每个区域的比例并不是固定的，G1会动态调节，当然也能通过-XX:G1NewSizePercent=5和-XX:G1MaxNewSizePercent=60来设置年轻代占比。
每个region的大小为1MB~32MB，且必须是2的幂 (-XX:G1HeapRegionSize=n 手动设置region大小)。默认将整堆划分为2048个分区，分区个数不一定需要为2的幂(网络上很多说分区个数也要为2的幂，实测后这是不对的)。在uf4b-app服务中，分配给pod的JVM堆内存大小为1536M，则该服务有1536个region，每个region有1M。
关于GC：G1提供了两种GC模式，Young GC和Mixed GC，两种都是完全Stop The World的。
YoungGC在Eden区满时会触发，使用Rest确定分区内对象存活情况，结合Cset通过复制算法进行收集。
MixedGC在IHOP达到阈值时启动并发标记过程，标记结束后进行收集，收集算法与年轻代相同。
GC过程梳理：
- 应用程序启动时，会首先向服务器申请分配JVM内存，并将申请到的内存划分为许多大小相同的区域Region，这时的区域都是空闲状态 (Free regions)
- 当应用程序开始运行后，会持续产生新的对象，G1内存管理器会分配空闲区域(Free regions)作为年轻代的伊甸区(eden regions)存放这些新产生的对象。如果新产生的对象大于Region的一半，则直接放入老年区的大对象区域(Humongous Region)。
- G1 GC为了匹配软实时(soft real-time)的目标会动态调整年轻代的大小，当年轻代被填满后，就会触发Young GC，Young GC会对整个年轻代和大对象区域(Humongous Region)进行回收。Young GC结束后依然存活的对象，会被疏散到n(n>=1)个新的Survivor分区，或者是老年代。
- 当java heap占用达到IHOP定义的阈值之后(
-XX:InitiatingHeapOccupancyPercent=45老年代占整堆比，默认45%) ，在下一个Young GC开始的时候，同时开始进行并发标记。 - 并发标记(Concurrent Marking)和Young GC穿插执行，在并发标记的过程中可能会出现多次Young-only GC。
- 在并发标记的清理阶段(Cleanup，下图黄色大圆圈)，会直接回收无存活对象的分区。
- 当并发标记结束后，会根据
-XX:G1HeapWastePercent=5(G1中愿意浪费的堆的百分比，java8默认值10%) 设置的阈值判断是否需要执行Mixed GC。 - 在Mixed GC阶段，会对所有年轻代里的Region，外加根据global concurrent marking统计得出收集收益高的若干老年代Region进行回收。
- 当收集达到
-XX:G1HeapWastePercent设置的预期时，停止该混合回收阶段。混合回收最多执行-XX:G1MixedGCCountTarget=8次。 - 如果Mixed GC实在无法跟上程序分配内存的速度，导致老年代填满无法继续进行Mixed GC，就会退化为Serial old GC使用单线程进行FullGC来收集整个堆空间。注意G1本身并不提供full GC的。
回收周期说明：
- 图中的圆圈表示G1回收过程中的暂停：蓝色圆圈表示Young-only GC导致的暂停，红色圆圈表示Mixed GC导致的暂停，黄色圆圈表示有并发标记导致的暂停。
- 当java heap占用达到 IHOP 定义的阈值之后，下一个Young-only GC收集将也会进行并发标记的初始标记，如图中大蓝色圆圈。
- Young-only GC和Concurrent Marking阶段可以穿插执行，在Concurrent Marking的过程中可能会出现多次Young-only GC，而Mixed GC只能在Concurrent Marking阶段完成后才能执行。
- 当完成并发标记阶段后，不一定会立刻进行Mixed GC，也可能会进行几次Young-only GC后才会进行Mixed GC。（可能并没有达到
-G1HeapWastePercent设置的阈值，则无需进入下一步） - 蓝色圆圈数量多于红色圆圈数量，表示一般情况下，Young-only GC发生的次数往往要大于Mixed GC的次数，这也是G1努力使垃圾回收更加高效。
FullGC触发条件：
G1在以下场景中会触发Full GC，同时会在日志中记录to-space-exhausted以及Evacuation Failure：
- 从年轻代分区拷贝存活对象时，无法找到可用的空闲分区
- 从老年代分区转移存活对象时，无法找到可用的空闲分区
- 分配巨型对象时在老年代无法找到足够的连续分区（下为示意图，来自网络。Humongous Region分配，导致的内存耗尽）
由于G1的应用场合往往堆内存都比较大，所以Full GC的收集代价非常昂贵，应该避免Full GC的发生。
根据这些知识点梳理，uf4b-app发生FullGC更有可能是分配巨型对象导致的。因为在hera日志中显示，每次FullGC时，堆内存其实是还有很多的，并没有出现无内存可用的情况，所以可能性更多在于大对象无法找到连续region。但是关键问题在于，前面提到excel才15k，能有多大呢？uf4b-app一个region已经有1M，绰绰有余。看来具体原因还需到结合代码深究。
3.2 柳暗花明
事情迎来了转机。在新的一周上班时，彦棨那边定位到了data-report老年代内存激增现象的原因。查看当时hera发现，mysql调用量也存在激增。和旭阳和沟通了解后，原来此处是执行订单导出功能的定时任务，由于订单时间跨度长，订单数量太多，所以需要重复请求数据库。此处订单导出也是excel功能，并且导出了约8000条订单数据。
Mysql趋势图(找不到9月14的图片了，使用该日期替代)
这里就有问题了，同样都是excel导出功能，同样引起了服务内存的异常现象，但却表现不一致。
| 服务 | 功能 | 数据量 | 文件大小 | 现象 |
| uf4b-app | 群接龙订单excel导出 | 1(sheet)*10+(行) | 15k | FullGC |
| data-report | 商户营业数据excel导出 | 3(sheet)*8000+(行) | 1.8M | 老年代激增 |
为了一探究竟，还需要从代码出发。以下代码只用看注释内容就好。
uf4b-app:
public String exportOrders(JielongBatchRequest request) {
ArrayList<String> title = new ArrayList<>(Arrays.asList("序号", "接龙标题", "接龙号", "订单号", "收件人姓名", "联系电话", "收件地址", "付款时间", "支付金额", "订单状态"));
//List总数据<List行数据>
List<List<String>> data = new ArrayList<>();
//一些数据准备工作，此处省略代码
doSomething();
//excel相关操作
WritableWorkbook writableWorkbook = null;
String url = null;
try {
ByteArrayOutputStream os = new ByteArrayOutputStream();
//1.创建WritableWorkbook工作簿对象，并将其接入创建的文件
writableWorkbook = Workbook.createWorkbook(os);
//2.创建一个Sheet，第一个参数是sheet的名称，第二个参数是索引号
WritableSheet writableSheet = writableWorkbook.createSheet("sheet1", 0);
//3.在sheet中加入数据
//标题行
WritableCellFormat wcf = ExcelUtil.getTitleStyle();
writableSheet.setColumnView(0, 6);
writableSheet.setColumnView(1, 35);
writableSheet.setColumnView(2, 8);
writableSheet.setColumnView(3, 16);
writableSheet.setColumnView(4, 12);
writableSheet.setColumnView(5, 15);
writableSheet.setColumnView(6, 25);
if (JielongRemoteServiceImpl.DELIVERY_TYPE_PICKUP == jielong.getDeliveryType()) {
//如果是到店自提，不展示地址。将该列设置隐藏
writableSheet.setColumnView(6, 0);
}
writableSheet.setColumnView(7, 15);
writableSheet.setColumnView(8, 10);
writableSheet.setColumnView(9, 10);
writableSheet.setColumnView(10, 14);
writableSheet.setColumnView(11, 14);
writableSheet.setColumnView(12, 14);
writableSheet.setColumnView(13, 14);
// 设置表头行高
writableSheet.setRowView(0, 650);
for (int i = 0; i < title.size(); i++) {
//new Label(列号，行号，内容)
writableSheet.addCell(ExcelUtil.getLabel(i, 0, title.get(i), wcf));
}
//内容
wcf = ExcelUtil.getTextStyle();
for (int i = 0; i < data.size(); i++) {
//设置行高
writableSheet.setRowView(i + 1, 600);
//第一列为编号
writableSheet.addCell(ExcelUtil.getLabel(0, i + 1, i + 1 + "", wcf));
//每行的数据
for (int j = 0; j < data.get(i).size(); j++) {
//填充这一行的每个单元格
writableSheet.addCell(ExcelUtil.getLabel(j + 1, i + 1, data.get(i).get(j), wcf));
}
}
//4.对WritableWorkbook对象执行写入操作
writableWorkbook.write();
//5.关闭writableWorkbook
writableWorkbook.close();
byte[] content = os.toByteArray();
InputStream is = new ByteArrayInputStream(content);
String key = "jielong/" + jielong.getSn() + System.currentTimeMillis() + ".xls";
ossBizService.uploadJielongExcel(key, is, os.size());
url = ossBizService.getJielongExcelUrl(key);
} catch (Exception e) {
e.printStackTrace();
} finally {
//ByteArrayInputStream和ByteArrayOutputStream无须关闭。
if (writableWorkbook != null) {
try {
writableWorkbook.close();
} catch (Exception e) {
e.printStackTrace();
}
}
}
return url;
}data-report:
public void doExecuteTask(ReportOrderExportTask reportOrderExportTask) {
try {
orderExportTaskMapper.updateByPrimaryKeySelective(ReportOrderExportTask.builder()
.id(reportOrderExportTask.getId())
.taskStartTime(DateTimeUtils.currentTimeMillis())
.mtime(DateTimeUtils.currentTimeMillis()).build());
// 1. 查询原始订单数据
OrderExportOriginalDataDTO orderExportOriginalDataDTO = fetchOrderExportData(reportOrderExportTask);
// 2. 转换构建导出数据
OrderExportDataDTO orderExportDataDTO = orderExportDataBuildService.buildOrderExportData(orderExportOriginalDataDTO);
// 文件名称格式化和组织
String localFileName = doSomething();
String fileShowName = doSomething();
// 3. 生成文件,在当前服务目录中临时暂存,返回的是绝对路径的文件名
String fileAbsolutePath = EasyExcelUtil.orderDetailWrite(localFileName,
orderExportDataDTO.getOrderExcels(),
orderExportDataDTO.getOrderExportGoodsExcels(),
orderExportDataDTO.getOrderExportPayExcels(),
orderExportDataDTO.getOrderExportRedeemExcels(),
orderExportDataDTO.getOrderExportStatisticsExcel());
// 4. 上传文件到 OSS,并获得 OSS 的下载地址
String downloadUrl = ossClientUtil.fileUpload(fileAbsolutePath, fileShowName, DateTimeConstants.MILLIS_PER_DAY * fileExpireDay);
// 5. 更新导出任务的 OSS 文件下载地址和过期时间
reportOrderExportTask.setFileUrl(downloadUrl);
orderExportTaskMapper.updateByPrimaryKeySelective(ReportOrderExportTask.builder()
.id(reportOrderExportTask.getId())
.fileUrl(downloadUrl)
.fileExpireTime(DateTimeUtils.currentTimeMillis() + (long) DateTimeConstants.MILLIS_PER_DAY * fileExpireDay)
.mtime(DateTimeUtils.currentTimeMillis())
.build());
// 6. 检查是否 B 端用户提交,是的话发送邮件
if (TaskSourcePlatformEnum.U4FB == TaskSourcePlatformEnum.fromCode(reportOrderExportTask.getTaskSourcePlatform())) {
sendEmail(reportOrderExportTask, orderExportDataDTO.getStoreDetailResponse());
}
// 7. 更新任务状态为 SUCCESS
orderExportTaskMapper.updateByPrimaryKeySelective(ReportOrderExportTask.builder()
.id(reportOrderExportTask.getId())
.taskStatus(OrderExportTaskStatusEnum.SUCCESS.getCode())
.taskFinishTime(DateTimeUtils.currentTimeMillis())
.mtime(DateTimeUtils.currentTimeMillis())
.build());
} catch (Exception e) {
log.error("执行订单导出任务失败,taskId:{}", reportOrderExportTask.getId(), e);
orderExportTaskMapper.updateByPrimaryKeySelective(ReportOrderExportTask.builder()
.taskStatus(OrderExportTaskStatusEnum.FAIL.getCode())
.taskFinishTime(DateTimeUtils.currentTimeMillis())
.id(reportOrderExportTask.getId())
.mtime(DateTimeUtils.currentTimeMillis())
.build());
} finally {
// 执行结束记得将计数器减 1
long incr = redisUtil.decr(ORDER_EXPORT_TASK_EXECUTE_CONCURRENT_COUNT_KEY, 1);
log.info("任务 {} 结束执行,当前并发任务数 {}", reportOrderExportTask.getId(), incr);
}
}在比较两个服务的excel导出方法后，发现了最致命的差别！关于excel的工具类jar包，data-report服务使用的是easyExcel的框架，而uf4b-app中使用的是jxl框架。我们现在跟excel相关的功能，一般都用easyExcel框架。easyExcel更轻量，且支持流式操作。而jxl是比较老的excel框架，它不能支持流式操作，所以通常需要将excel所需要所有信息(数据、格式、字体、颜色等等)加载到内存。在此，我试着结合现象和代码分析一下，给出可能的结论。
data-report：
查询到订单数据，easyExcel通过流式写入将文件暂存在本地。由于是写入流，不需要一次性申请大量内存空间(即无大对象产生Humongous Region)，只需保证当前一批的写入对象具有足够空间(Eden)。由于写入时间较长，这段时间内每一批写入对象一直存在引用(方法未结束)，故在YoungGC后会由于分代年龄过大(-XX:MaxTenuringThreshold=15)进入到老年代。在持续时间内，Eden区持续被填满，对象持续进入到老年代，因此就展现出了疯狂YoungGC，老年代内存飙升的现象。
uf4b-app：
jxl框架会将所有excel数据在内存中准备好，可以理解为在内存中将Excel画好。看了源代码发现，最逆天的是每个cell单元格都new了一个对象。当然，整个Excel表格大对象并不是Humongous Region大对象，真正的大对象是在将Excel大对象上传至OSS时，所使用的byte[]数组，该数组在声明时就申请了大量连续内存。
byte[] content = os.toByteArray();
InputStream is = new ByteArrayInputStream(content);
//os.toByteArray()的代码
public synchronized byte toByteArray()[] {
return Arrays.copyOf(buf, count);
}那么这个buf有多大呢，我在使用测试环境大概10条订单的群接龙导出进行debug时发现，这个buf数组有27336个byte。27336/1024=26.7M(当时这里算错了😭，其实是26.7K，导致思路有误差，一直认定是大对象导致的，文章后续排查思路都以26.7M推进)，由于大对象占用连续region，则这里需要连续27个region。 况且这里是Arrays.copyOf(buf, count)，所以一共需要两个这么大的连续空间。我认为对于每个rgion为1M的uf4b-app服务来说，这连续空间的数量有些夸张了。
4.情景复现
至此，uf4b-app服务频繁FullGC原因已大致清晰了起来，我认为(划重点，我认为)：群接龙导出excel方法使用过时的jxl工具类，产生了巨大对象，在内存区域中找不到连续的空间，故发生了FullGC
为了情景再现，本着严谨的精神，这里使用阿里开源工具arthas和GC日志，模拟uf4b-app线上环境进行本地调试。
4.1接入Arthas
1.设置jvm参数，与线上uf4b-app一致
-Xmx1536m
-Xms1536m
-XX:+UseG1GC
-XX:MaxGCPauseMillis=2002.引入arthas依赖
<dependency>
<groupId>com.taobao.arthas</groupId>
<artifactId>arthas-spring-boot-starter</artifactId>
<version>3.6.9</version>
</dependency>3.spring启动参数
arthas:
agent-id: uf4b-app-test #自定义服务在arthas中的名称
tunnel-server: 127.0.0.1:8563 # 远程管理平台arthas tunnel的地址
app-name: uf4b-app # 当前服务名，如果不配置agent-id会自动生成服务名加下划线随机值的agent-id启动项目后，浏览器进入127.0.0.1:8563即可到达程管理平台。页面展示如下
使用dashboard命令显示当前系统的实时数据面板，如CPU占比, 错误数, 线程池信息等。其他命令感兴趣可以去官网了解，此处不展开。本地启动项后，GC已经设置为G1，heap大小已经为1536M。刚启动完就有6次YoungGC，肯定是Spring初始化项目时产生的。
4.2请求回放
先随便用psotman本地调用几个方法，给服务上点压力，让heap堆里面有点垃圾，不要空空如也。
可以发现，现在YoungGC和FullGC都经历了一次。现在我们开启GC日志，方便一会儿群接龙实操时进行观察。打开如下两个选项之后，当应用发生 GC 时，就会在控制台打印 GC 日志。
$ vmoption PrintGC true
Successfully updated the vm option.
NAME BEFORE-VALUE AFTER-VALUE
------------------------------------
PrintGC false true
$ vmoption PrintGCDetails true
Successfully updated the vm option.
NAME BEFORE-VALUE AFTER-VALUE
-------------------------------------------
PrintGCDetails false true这里有点问题，不知道为何我在此处设置后，项目控制台并未打印。所以我在JVM启动参数中加入了打印详细GC日志参数。正式环境也可以将GC信息持久化到文本中，方便后续排查( -Xloggc:gc.log:这个参数可以设置将gc日志写入一个磁盘文件)。
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps重新启动项目，这次可以打印GC日志了。在管理页面使用$ vmtool --action forceGc 命令，强制GC一次，看看项目控制台打印。FullGC成功，无问题！
2023-10-06T19:57:12.890-0800: [Full GC (System.gc()) 94M->59M(1536M), 0.3918729 secs]
[Eden: 35.0M(839.0M)->0.0B(839.0M) Survivors: 0.0B->0.0B Heap: 94.9M(1536.0M)->60.0M(1536.0M)], [Metaspace: 77563K->77563K(1118208K)]
[Times: user=0.21 sys=0.12, real=0.39 secs]现在终于可以进行测试了～群接龙蠢蠢欲动。使用该curl请求，该条群接龙大概有十几条数据。
curl --location --request POST '127.0.0.1:8080/rpc/jielong/order' \\
--header 'Content-Type: application/json-rpc' \\
--data-raw '{
"jsonrpc": 2.0,
"method": "exportOrders",
"params": [
{
"jielong_id": 127,
"biz_store_id": "5c7e633e-1de3-4161-b072-71456e1265b1",
"status": 2
}
],
"id": 0
}'请求完成后，看到控制台打印了以下信息。
2023-10-06T22:10:33.465-0800: [Full GC (System.gc()) 107M->58M(1536M), 0.3566612 secs]
[Eden: 46.0M(727.0M)->0.0B(727.0M) Survivors: 0.0B->0.0B Heap: 108.0M(1536.0M)->58.3M(1536.0M)], [Metaspace: 79412K->79412K(1120256K)]
[Times: user=0.22 sys=0.10, real=0.36 secs]
2023-10-06 22:10:33.782 INFO 18733 --- [nio-8080-exec-4] c.w.p.uf4b.config.LogInvocationListener : rpc request不对啊，这个怎么跟刚才的强制FullGC一模一样啊。此时，我脑子里满是问号❓❓❓不是说大对象引起的FullGC要打印G1 Hunongous Allocation和 Evacuation Failur 吗？怎么和网络上其他人打印的大对象引起的GC日志不一样。此时，心里突然一惊，有个念头划过。。。不会吧，不会吧，这个jxl源码里面不会手动调了一次System.gc() 吧。 这里使用althas的trace命令，可以追踪方法调用路径上的开销和链路。下面追踪exportOrders方法的调用。
[arthas@14117]$ trace com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl exportOrders
Press Q or Ctrl+C to abort.
Affect(class count: 2 , method count: 2) cost in 491 ms, listenerId: 13
`---ts=2023-10-06 22:10:32;thread_name=http-nio-8080-exec-6;id=4f;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@1e42850e
`---[990.029792ms] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl$$EnhancerBySpringCGLIB$$7ef84c25:exportOrders()
`---[99.61% 986.120375ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[94.85% 935.287125ms ] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl:exportOrders()
+---[18.87% 176.473791ms ] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl:checkStore() #338
+---[0.01% 0.132041ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getJielongId() #339
+---[9.92% 92.813167ms ] com.wosai.pantheon.order.service.JielongService:getWithSumById() #339
+---[0.00% 0.019833ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getTotal() #344
+---[0.00% 0.031375ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:<init>() #346
+---[0.00% 0.020833ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getJielongId() #347
+---[0.00% 0.023042ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setJielongId() #347
+---[0.00% 0.011125ms ] com.wosai.pantheon.order.model.dto.PageDTO:<init>() #348
+---[0.00% 0.004875ms ] com.wosai.pantheon.order.model.dto.PageDTO:setPage() #349
+---[0.00% 0.005417ms ] com.wosai.pantheon.order.model.dto.PageDTO:setPageSize() #351
+---[0.00% 0.005875ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setPageDTO() #352
+---[0.00% 0.013708ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getStatus() #353
+---[0.00% 0.015375ms ] com.wosai.pantheon.order.enums.OrderStatus:getCode() #359
+---[0.00% 0.00225ms ] com.wosai.pantheon.order.enums.OrderStatus:getCode() #360
+---[0.00% 0.006125ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setStatusCollection() #358
+---[9.49% 88.790292ms ] com.wosai.pantheon.order.service.JielongOrderService:getJielongOrders() #362
+---[0.00% 0.045084ms ] com.wosai.web.api.PaginatedResult:getRecords() #362
+---[0.00% 0.039917ms ] org.apache.commons.collections.CollectionUtils:isNotEmpty() #363
+---[0.00% min=0.005167ms,max=0.015ms,total=0.025792ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getItemsInfo() #370
+---[0.00% min=0.004375ms,max=0.022ms,total=0.037916ms,count=3] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getId() #371
+---[0.00% 0.042709ms ] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getId() #372
+---[0.00% 0.0225ms ] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getName() #372
+---[0.00% min=0.0015ms,max=0.013292ms,total=0.019542ms,count=3] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getTitle() #390
+---[0.00% min=0.001917ms,max=0.0065ms,total=0.010876ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getOrderSeq() #391
+---[0.00% min=0.0015ms,max=0.007959ms,total=0.014043ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getSn() #392
+---[0.00% min=0.002125ms,max=0.005167ms,total=0.011375ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getOrderAddress() #393
+---[0.00% min=0.001042ms,max=0.017333ms,total=0.021ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getCtime() #402
+---[0.14% min=0.010375ms,max=1.215583ms,total=1.294249ms,count=3] com.wosai.common.utils.WosaiDateTimeUtils:format() #402
+---[0.00% min=0.001125ms,max=0.005125ms,total=0.008375ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getEffectiveAmount() #403
+---[0.00% min=0.001083ms,max=0.004708ms,total=0.011333ms,count=6] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getStatus() #405
+---[0.00% min=0.001125ms,max=0.002916ms,total=0.005999ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getItemsInfo() #407
+---[0.36% 3.393833ms ] jxl.Workbook:createWorkbook() #420
+---[0.03% 0.303292ms ] jxl.write.WritableWorkbook:createSheet() #422
+---[0.01% 0.052792ms ] com.wosai.pantheon.uf4b.util.ExcelUtil:getTitleStyle() #425
+---[0.08% 0.713667ms ] jxl.write.WritableSheet:setColumnView() #426
+---[0.06% 0.528833ms ] jxl.write.WritableSheet:setColumnView() #427
+---[0.03% 0.319333ms ] jxl.write.WritableSheet:setColumnView() #428
+---[0.01% 0.074917ms ] jxl.write.WritableSheet:setColumnView() #429
+---[0.00% 0.003042ms ] jxl.write.WritableSheet:setColumnView() #430
+---[0.00% 0.001375ms ] jxl.write.WritableSheet:setColumnView() #431
+---[0.00% 0.001458ms ] jxl.write.WritableSheet:setColumnView() #432
+---[0.00% 0.007042ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getDeliveryType() #433
+---[0.03% 0.287458ms ] jxl.write.WritableSheet:setColumnView() #435
+---[0.02% 0.186459ms ] jxl.write.WritableSheet:setColumnView() #437
+---[0.00% 0.00175ms ] jxl.write.WritableSheet:setColumnView() #438
+---[0.00% 0.001458ms ] jxl.write.WritableSheet:setColumnView() #439
+---[0.00% 0.001334ms ] jxl.write.WritableSheet:setColumnView() #440
+---[0.00% 0.002792ms ] jxl.write.WritableSheet:setColumnView() #441
+---[0.00% 0.001958ms ] jxl.write.WritableSheet:setColumnView() #442
+---[0.00% 0.001334ms ] jxl.write.WritableSheet:setColumnView() #443
+---[0.02% 0.150833ms ] jxl.write.WritableSheet:setRowView() #445
+---[0.02% min=0.001125ms,max=0.115042ms,total=0.180167ms,count=11] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #448
+---[0.17% min=0.001125ms,max=1.292417ms,total=1.606709ms,count=11] jxl.write.WritableSheet:addCell() #448
+---[0.00% 0.00875ms ] com.wosai.pantheon.uf4b.util.ExcelUtil:getTextStyle() #451
+---[0.00% min=0.002125ms,max=0.010625ms,total=0.01525ms,count=3] jxl.write.WritableSheet:setRowView() #454
+---[0.00% min=0.002083ms,max=0.004459ms,total=0.009708ms,count=3] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #456
+---[0.01% min=0.00225ms,max=0.048167ms,total=0.059625ms,count=3] jxl.write.WritableSheet:addCell() #456
+---[0.01% min=0.001125ms,max=0.011625ms,total=0.069917ms,count=30] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #460
+---[0.01% min=0.001083ms,max=0.009917ms,total=0.051751ms,count=30] jxl.write.WritableSheet:addCell() #460
+---[1.06% 9.94075ms ] jxl.write.WritableWorkbook:write() #464
+---[0.00% 0.009125ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getSn() #469
+---[7.07% 66.151291ms ] com.wosai.pantheon.uf4b.service.OssBizService:uploadJielongExcel() #470
+---[1.19% 11.111542ms ] com.wosai.pantheon.uf4b.service.OssBizService:getJielongExcelUrl() #471
`---[43.81% 409.7575ms ] jxl.write.WritableWorkbook:close() #478可以看到最终在 jxl.write.WritableWorkbook:close() 的路径上耗费了大量时间409ms，刚好大于FullGC耗时的360ms，有理由怀疑在这个方法内部进行了FullGC。由于trace每次只能跟踪一级方法的调用链路，并不会向下trace多层，那么这里可以继续对子方法使用trace命令，也可以看源码，我直接点进去看了。
好家伙，做梦都没想到成熟的开源框架里面有手动gc。于是我再次debug断点，果然到这个if判断的时候条件为true，执行了gc。分析代码发现gcDisabled参数默认为false，可以手动设置。故修改代码，将gcDisabled 的值设置为true。
重新启动项目，再次调用接口，观察控制台和trace追踪。
2023-10-06 22:38:16.753 INFO 18733 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring FrameworkServlet 'dispatcherServlet'
2023-10-06 22:38:16.760 INFO 18733 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization started
2023-10-06 22:38:17.104 INFO 18733 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : FrameworkServlet 'dispatcherServlet': initialization completed in 343 ms
2023-10-06 22:38:20.331 INFO 18733 --- [nio-8080-exec-1] c.w.p.uf4b.config.LogInvocationListener : rpc request`---ts=2023-10-06 22:38:17;thread_name=http-nio-8080-exec-1;id=4d;is_daemon=true;priority=5;TCCL=org.springframework.boot.context.embedded.tomcat.TomcatEmbeddedWebappClassLoader@5b213e10
`---[2966.254833ms] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl$$EnhancerBySpringCGLIB$$49f3cc8:exportOrders()
`---[99.98% 2965.558583ms ] org.springframework.cglib.proxy.MethodInterceptor:intercept()
`---[82.39% 2443.414667ms ] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl:exportOrders()
+---[5.56% 135.960042ms ] com.wosai.pantheon.uf4b.rpc.JielongOrderRemoteServiceImpl:checkStore() #339
+---[0.00% 0.018833ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getJielongId() #340
+---[4.11% 100.389708ms ] com.wosai.pantheon.order.service.JielongService:getWithSumById() #340
+---[0.00% 0.011834ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getTotal() #345
+---[0.00% 0.041208ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:<init>() #347
+---[0.01% 0.230125ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getJielongId() #348
+---[0.00% 0.010375ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setJielongId() #348
+---[0.00% 0.101125ms ] com.wosai.pantheon.order.model.dto.PageDTO:<init>() #349
+---[0.00% 0.009917ms ] com.wosai.pantheon.order.model.dto.PageDTO:setPage() #350
+---[0.00% 0.010959ms ] com.wosai.pantheon.order.model.dto.PageDTO:setPageSize() #352
+---[0.00% 0.008875ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setPageDTO() #353
+---[0.00% 0.009ms ] com.wosai.pantheon.uf4b.dto.request.JielongBatchRequest:getStatus() #354
+---[0.00% 0.013834ms ] com.wosai.pantheon.order.enums.OrderStatus:getCode() #360
+---[0.00% 0.00975ms ] com.wosai.pantheon.order.enums.OrderStatus:getCode() #361
+---[0.00% 0.007625ms ] com.wosai.pantheon.order.model.dto.request.JielongOrderBaseQueryRequest:setStatusCollection() #359
+---[5.20% 127.017833ms ] com.wosai.pantheon.order.service.JielongOrderService:getJielongOrders() #363
+---[0.00% 0.008666ms ] com.wosai.web.api.PaginatedResult:getRecords() #363
+---[0.51% 12.566709ms ] org.apache.commons.collections.CollectionUtils:isNotEmpty() #364
+---[0.00% min=0.002292ms,max=0.012084ms,total=0.017543ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getItemsInfo() #371
+---[0.00% min=0.002167ms,max=0.007459ms,total=0.016501ms,count=3] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getId() #372
+---[0.00% 0.003041ms ] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getId() #373
+---[0.00% 0.00425ms ] com.wosai.pantheon.order.model.dto.ItemDigestDTO:getName() #373
+---[0.00% min=0.003333ms,max=0.012209ms,total=0.022417ms,count=3] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getTitle() #391
+---[0.00% min=0.003125ms,max=0.006125ms,total=0.012625ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getOrderSeq() #392
+---[0.00% min=0.002209ms,max=0.007667ms,total=0.013501ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getSn() #393
+---[0.00% min=0.002375ms,max=0.006291ms,total=0.012083ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getOrderAddress() #394
+---[0.00% min=0.002333ms,max=0.006375ms,total=0.013833ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getCtime() #403
+---[0.40% min=0.013666ms,max=9.784459ms,total=9.871333ms,count=3] com.wosai.common.utils.WosaiDateTimeUtils:format() #403
+---[0.00% min=0.002417ms,max=0.009709ms,total=0.014584ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getEffectiveAmount() #404
+---[0.00% min=0.00225ms,max=0.013459ms,total=0.033669ms,count=6] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getStatus() #406
+---[0.00% min=0.0025ms,max=0.006ms,total=0.0115ms,count=3] com.wosai.pantheon.order.model.dto.JielongOrderDTO:getItemsInfo() #408
+---[0.04% 0.965875ms ] jxl.WorkbookSettings:<init>() #421
+---[0.00% 0.0065ms ] jxl.WorkbookSettings:setGCDisabled() #422
+---[1.24% 30.352125ms ] jxl.Workbook:createWorkbook() #423
+---[0.39% 9.5755ms ] jxl.write.WritableWorkbook:createSheet() #425
+---[0.10% 2.427333ms ] com.wosai.pantheon.uf4b.util.ExcelUtil:getTitleStyle() #428
+---[0.05% 1.20825ms ] jxl.write.WritableSheet:setColumnView() #429
+---[0.01% 0.315083ms ] jxl.write.WritableSheet:setColumnView() #430
+---[0.01% 0.177333ms ] jxl.write.WritableSheet:setColumnView() #431
+---[0.00% 0.006459ms ] jxl.write.WritableSheet:setColumnView() #432
+---[0.00% 0.006167ms ] jxl.write.WritableSheet:setColumnView() #433
+---[0.00% 0.004625ms ] jxl.write.WritableSheet:setColumnView() #434
+---[0.00% 0.011709ms ] jxl.write.WritableSheet:setColumnView() #435
+---[0.00% 0.008875ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getDeliveryType() #436
+---[0.00% 0.023125ms ] jxl.write.WritableSheet:setColumnView() #438
+---[0.00% 0.004958ms ] jxl.write.WritableSheet:setColumnView() #440
+---[0.00% 0.006ms ] jxl.write.WritableSheet:setColumnView() #441
+---[0.00% 0.008917ms ] jxl.write.WritableSheet:setColumnView() #442
+---[0.00% 0.005ms ] jxl.write.WritableSheet:setColumnView() #443
+---[0.00% 0.007792ms ] jxl.write.WritableSheet:setColumnView() #444
+---[0.00% 0.00525ms ] jxl.write.WritableSheet:setColumnView() #445
+---[0.00% 0.009708ms ] jxl.write.WritableSheet:setColumnView() #446
+---[0.01% 0.164625ms ] jxl.write.WritableSheet:setRowView() #448
+---[0.07% min=0.002542ms,max=1.768542ms,total=1.812541ms,count=11] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #451
+---[0.02% min=0.003375ms,max=0.476041ms,total=0.52304ms,count=11] jxl.write.WritableSheet:addCell() #451
+---[0.01% 0.178208ms ] com.wosai.pantheon.uf4b.util.ExcelUtil:getTextStyle() #454
+---[0.00% min=0.004416ms,max=0.008ms,total=0.017291ms,count=3] jxl.write.WritableSheet:setRowView() #457
+---[0.00% min=0.003791ms,max=0.08975ms,total=0.099832ms,count=3] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #459
+---[0.00% min=0.00425ms,max=0.010208ms,total=0.019749ms,count=3] jxl.write.WritableSheet:addCell() #459
+---[0.06% min=0.002417ms,max=0.519ms,total=1.482086ms,count=30] com.wosai.pantheon.uf4b.util.ExcelUtil:getLabel() #463
+---[0.01% min=0.003ms,max=0.07325ms,total=0.207791ms,count=30] jxl.write.WritableSheet:addCell() #463
+---[3.43% 83.810208ms ] jxl.write.WritableWorkbook:write() #467
+---[0.00% 0.011667ms ] com.wosai.pantheon.order.model.dto.JielongWithSumAndGoodsDTO:getSn() #472
+---[77.46% 1892.62375ms ] com.wosai.pantheon.uf4b.service.OssBizService:uploadJielongExcel() #473
+---[0.45% 10.966917ms ] com.wosai.pantheon.uf4b.service.OssBizService:getJielongExcelUrl() #474
`---[0.13% 3.280792ms ] jxl.write.WritableWorkbook:close() #481果然控制台并没有打印GC日志，trace中显示jxl.write.WritableWorkbook:close() 仅仅耗时3毫秒，也说明之前是该方法中的手动gc耗时过高。
既然FullGC不是由大对象引起的，再重启一次项目看看调用群接龙前后堆内存的变化。
观察发现，调用后eden和old区域都加了一点点，并没有发生GC。说明大对象根本不构成影响，空闲区(free region)是充足的。
4.2真相大白
至此，一切都真相大白！uf4b-app频繁FullGC真实原因是因为jxl框架源码主动调用了 System.gc()，而不是之前猜想的分配Humongous大对象导致的空间不足。
5.优化方案
5.1项目优化
uf4b-app项目中添加setting.setGCDisabled(true)代码。
5.2JVM优化
虽然本次排查发现，问题并不是内存分配导致的，也不需要进行jvm调优，但是在过程中探索了大对巨型对象导致内存耗尽的问题，这里也一并说明。
巨型会独占一个、或多个连续分区，其中第一个分区被标记为开始巨型(StartsHumongous)，相邻连续分区被标记为连续巨型(ContinuesHumongous)。由于无法享受TLab带来的优化，并且确定一片连续的内存空间需要扫描整堆，因此确定巨型对象开始位置的成本非常高，如果可以，应用程序应避免生成巨型对象。
解决方案：
- 首先要分析程序中频繁产生巨型对象是否正常，比常见的如查询sql没有加limit导致返回的数据量过大、或者代码是否有在内存中申请大量空间，而不是直接增加Region的大小。
- 通过
-XX: G1HeapRegionSize选项来增加内存区域Region的大小，提升Region对象的判断标准，以减少巨大对象的数量。 - 增加堆java的大小使得有更多的空间来存放巨型对象
- 通过
-XX:G1MaxNewSizePercent降低年轻代Region的占比，给老年代预留更多的空间，从而给巨型对象提供给多的内存空间。当然，不建议手动调整该参数，G1比人更智能。 - 通过
-XX:G1ReservePercent增加“to-space”的预留内存量。同上，不建议手动修改。
5.3建议
- 尽量使用久经考验但不陈旧的框架。例如使用fastjson1而不是fastjson2。这个jxl千万不要再用了，毕竟十几年了，当时大神写的手动gc肯定是有所考量。
- 技术部门可以引入Arthas，方便线上问题定位和排查。
- 框架组可以提供gc日志。我们hera上的数据都是从gc日志加工来的，框架组若是提供一手资源，更方便我们直接结合代码定位。
6.结语
终于完成这一篇排查分析的文章。现在回过头来看，在整个排查过程中一波三折，我可以说是处处都走了弯路。若是第一天就百度“jxl引起的fullGC”，那可能半小时就能把问题定位解决了。不过我也并不觉得浪费了时间和精力。在这段时间，有机会比较全面地了解了G1、掌握了一些关于G1的调优知识、也尝试了Arthas的使用，总的来说收获满满。JVM真是深不见底，想要深入研究需要长时间的积累。路漫漫其修远兮，吾将上下而求索。
7.附录
常用G1设置参数
建议不要手动设置，使用默认设置就挺好。
| Option and Default Value | Description | 说明 |
|
| The goal for the maximum pause time. | 设置最长暂停时间目标值，默认是200毫秒 |
|
| The goal for the maximum pause time interval. By default G1 doesn’t set any goal, allowing G1 to perform garbage collections back-to-back in extreme cases. | 最大暂停时间间隔，一般不设置 |
|
| The maximum number of threads used for parallel work during garbage collection pauses. This is derived from the number of available threads of the computer that the VM runs on in the following way: if the number of CPU threads available to the process is fewer than or equal to 8, use that. Otherwise add five eighths of the threads greater than to the final number of threads. | 设置STW并行工作的GC线程数，一般推荐设置该值为逻辑处理器的数量，最大是8；如果逻辑处理器大于8，则取逻辑处理器数量的5/8；这适用于大多数情况，除非是较大的SPARC系统，其中的n值可以是逻辑处理器的5/16 |
|
| The maximum number of threads used for concurrent work. By default, this value is divided by 4.-XX:ParallelGCThreads | 并发标记阶段，并发执行的线程数，一般n值为并行垃圾回收线程数（ParallelGCThreads）的1/4左右 |
|
| Defaults for controlling the initiating heap occupancy indicate that adaptive determination of that value is turned on, and that for the first few collection cycles G1 will use an occupancy of 45% of the old generation as mark start threshold. | 设置触发全局并发标记周期的老年代在堆内存中占比，默认占用率阈值是45% |
|
| The set of the heap region size based on initial and maximum heap size. So that heap contains roughly 2048 heap regions. The size of a heap region can vary from 1 to 32 MB, and must be a power of 2. | 设置 G1区域Region的大小。范围从1 MB 到32MB之间，目标是根据最小的 Java 堆大小划分出大约2048个区域。 |
|
| The size of the young generation in total, which varies between these two values as percentages of the current Java heap in use. | 设置年轻代最小值和最大值占总堆的百分比，默认值是5%～60% |
|
| The allowed unreclaimed space in the collection set candidates as a percentage. G1 stops the space-reclamation phase if the free space in the collection set candidates is lower than that. | 设置G1中愿意浪费的堆的百分比，如果可回收region的占比小于该值，默认值10% |
|
| The expected length of the space-reclamation phase in a number of collections. | 一次全局并发标记后，最多执行Mixed GC的次数，次数越多，单次回收的老年代的Region个数就越少，暂停也就越短 |
|
| Old generation regions with higher live object occupancy than this percentage aren't collected in this space-reclamation phase. | 老年代Region中存活对象的占比，只有当占比小于此参数的Old Region，才会被选入CSet。这个值越大，说明允许回收的Region中的存活对象越多，可回收的空间就越少，gc效果就越不明显 |
正常的MixedGC展示：
data-report服务。未发生FullGC，但清理了老年代region。平均耗时1200/16=75ms，符合-XX:MaxGCPauseMillis=200 时间范围内尽可能将老年代的回收效益最大化(-XX:G1MixedGCLiveThresholdPercent=85参数设置，当存活对象占比低于85%时，才会清理该region，以提高gc的效果)
真正的大对象
此处分配一个100M的大对象，看看真实情况。
//看看真正的巨无霸对象会怎么样
byte[] bytes = new byte[100*1024*1024];2023-10-07T00:15:15.057-0800: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.1261500 secs]
[Parallel Time: 80.9 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 4685753.5, Avg: 4685753.8, Max: 4685754.3, Diff: 0.8]
[Ext Root Scanning (ms): Min: 18.5, Avg: 19.1, Max: 19.9, Diff: 1.4, Sum: 153.1]
[Update RS (ms): Min: 4.5, Avg: 7.7, Max: 14.7, Diff: 10.2, Sum: 61.2]
[Processed Buffers: Min: 1, Avg: 6.0, Max: 12, Diff: 11, Sum: 48]
[Scan RS (ms): Min: 0.0, Avg: 0.8, Max: 2.8, Diff: 2.8, Sum: 6.7]
[Code Root Scanning (ms): Min: 0.0, Avg: 2.2, Max: 8.4, Diff: 8.4, Sum: 17.7]
[Object Copy (ms): Min: 10.5, Avg: 20.1, Max: 34.4, Diff: 24.0, Sum: 160.7]
[Termination (ms): Min: 16.7, Avg: 30.1, Max: 40.2, Diff: 23.5, Sum: 240.6]
[Termination Attempts: Min: 40, Avg: 76.4, Max: 113, Diff: 73, Sum: 611]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 1.7]
[GC Worker Total (ms): Min: 79.7, Avg: 80.2, Max: 80.5, Diff: 0.9, Sum: 641.7]
[GC Worker End (ms): Min: 4685834.0, Avg: 4685834.0, Max: 4685834.0, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 13.0 ms]
[Other: 32.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 20.0 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.0 ms]
[Humongous Register: 1.3 ms]
[Humongous Reclaim: 1.9 ms]
[Free CSet: 4.3 ms]
[Eden: 786.0M(910.0M)->0.0B(916.0M) Survivors: 4096.0K->5120.0K Heap: 1402.5M(1536.0M)->54.3M(1536.0M)]
[Times: user=0.19 sys=0.11, real=0.13 secs]
2023-10-07T00:15:15.184-0800: [GC concurrent-root-region-scan-start]
2023-10-07T00:15:15.188-0800: [GC concurrent-root-region-scan-end, 0.0044508 secs]
2023-10-07T00:15:15.188-0800: [GC concurrent-mark-start]
2023-10-07T00:15:15.286-0800: [GC concurrent-mark-end, 0.0980202 secs]
2023-10-07T00:15:15.288-0800: [GC remark 2023-10-07T00:15:15.288-0800: [Finalize Marking, 0.0003700 secs] 2023-10-07T00:15:15.289-0800: [GC ref-proc, 0.0020012 secs] 2023-10-07T00:15:15.291-0800: [Unloading, 0.1080086 secs], 0.1109636 secs]
[Times: user=0.08 sys=0.16, real=0.11 secs]
2023-10-07T00:15:15.400-0800: [GC cleanup 156M->156M(1536M), 0.0012991 secs]
[Times: user=0.00 sys=0.01, real=0.00 secs]发现出现了Humongous Allocatio字眼，但是是YoungGC，并没有产生FullGC。是因为我在测试时，基本没有什么old区域的对象，一直重复调用该方法产生的巨无霸对象都在Humongous区。marking 阶段之后的cleanup阶段中释放Humongous区，所以此处是YoungGC伴随着并发标记的流程。
参考：
Garbage-First Garbage Collector (oracle.com)
GC - Java 垃圾回收器之G1详解 | Java 全栈知识体系 (pdai.tech)
深入理解JVM - G1收集器-阿里云开发者社区 (aliyun.com)
关于 G1 GC 的一些研究 - 知乎 (zhihu.com)
4412
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
