index_new5.html
../../../zaker_core/zaker_tpl_static/wap/tpl_guoji1.html
![]()
本文以线上环境内存告警排查为例，演示排查过程和思路。通过分析dump文件和GC日志，确定了内存告警原因是大量不可达对象占用老年代且未触发FullGC回收。进一步排查发现，这些对象主要是NioChannel对象，来源于监控数据上报接口。通过调整JVM参数触发MixedGC和优化代码减少NioChannel产生，成功解决了内存告警问题。
🔍 问题分析：通过分析dump文件和GC日志，确定了内存告警原因是大量不可达对象占用老年代且未触发FullGC回收。
📈 原因排查：进一步排查发现，这些对象主要是NioChannel对象，来源于监控数据上报接口。分析发现，服务端在接受客户端数据上报时，存在QPS峰值>500的情况，导致NioChannel对象大量产生。
💡 解决方案：通过调整JVM参数触发MixedGC释放老年代空间，并通过优化代码减少NioChannel对象的产生，成功解决了内存告警问题。
竹达 2025-09-04 08:30 浙江
这是2025年的第98篇文章
（ 本文阅读时间：15分钟 ）
核心启动参数：-Xms4915m -Xmx4915m -XX:+UseG1GC -XX:InitiatingHeapOccupancyPercent=40 -XX:-G1UseAdaptiveIHOP -XX:G1HeapRegionSize=16m -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:MaxDirectMemorySize=1g -XX:SurvivorRatio=10 -XX:+ExplicitGCInvokesConcurrent -XX:MarkStackSize=4194304
总结一下JVM配置：堆大小5g，每个Region为16m，堆外1g，元空间最大512m，新生代和老年代空间自动调配（幸存区是伊甸园的十分之一），最大线程栈空间是4m。按照常驻线程大约1000个，所以JVM内存峰值也就是 5g+1g+512m+4g > 8g ，肯定会在运行过程中触发内存使用告警的噻！不过不用担心！这种情况超内存运行的情况是不会存在的，因为到90%的内存使用率的时候，告警来啦！！！在10:10左右触发的 内存使用率大于90%的告警。此时CPU使用率和网络流量并没有什么飙升，从内存的监控上也可以看到，这个使用率是慢慢爬升的，而不是飙升的。我们的机器规格是4C-8G的，所以如果达到内存使用率为90%，对内存的使用情况是要重点关注的。从下图可以明显地看到，使用的G1_Old区域爬升明显（左一红线）。内存使用情况 - 重点关注左边红色线条 在这里强调一下，对于线上的问题应该是先止血！我们这个应用的内存还有些剩余，所以我先进行了一次dump，然后再执行了一下FullGC的触发操作。你还别说，这一触发FullGC之后，整个机器内存就清爽了。FullGC之后内老年代明显下降 接下来我们分析，老年代爬升的原因是什么呢？在dump文件中发现存在内存泄露报表，并且里面很多不可达的对象没有被回收。内存泄漏报表不可达对象信息 2万多在执行了FullGC之后，比对了新的dump数据，发现这些Unreachable的对象的确都被回收了。实际上问题就是因为一大堆的不可达对象，占用了老年代并且没有触发FullGC，从而导致了内存使用较高引发的告警。1.第一个问题：这些对象怎么进入到old区的呢？其实无非就是三种情况a.途经1：长生命周期的对象，没有被YGC回收掉，所以进入老年代。b.途经2：大对象！对象占用的堆内存空间大于或等于默认的堆最小分块单位Region的大小1/2。c.途经3：提前晋升对象，在发生YGC的时候，存活对象的内存占用超出survivor区域，导致部分对象“未老先升”！2.第二个问题：进入到老年代了，为什么没有触发老年代不可达对象的回收呢？a.猜想1：对象存在引用（这里很显然不符合这个现象，因为都是不可达的）b.猜想2：空间使用没有达到MixedGC的回收标准，所以不会被MixedGC回收。c.猜想3：老年代的空间没有触发FullGC的标准，所以没有引发FullGC回收。3.第三个问题：为什么会产生这么多NioChannel对象？真的需要这么多么？生命周期排查到目前为止，并JavaTools没有什么直接的方式去获取对象的生命周期。所以我们无法确定是不是因为经历了15次的YoungGC之后进入的老年代。不过可以确定的是， 我们这台机器的YGC平均间隔再30s以上。如果是走正规渠道进来的对象，那么存活时间应该要再5分钟以上。对于这些不可达的NioChannel来说，实际上是对SocketChannel的包装，除非本次链接时间很长，否则不可能存活这么久！只讨论对象是没有任何意义的，要知道这个对象是怎么来的？从dump的分析平台上（Grace平台），我们看到对象的属性信息，其中更有一个属性叫sc，这个Niochannel里面代表的是SocketChannel ，能够确定的通道实际上是从自己的服务过来的。当然了，不奇怪就是自己相同Container中的 Nginx代理过来的。既然有了这么详细的属性，作为一个Http协议产生的Channel一定还有Http层面的接口信息。一层层展开属性，有价值线索的uri信息（这个过程需要先找到类信息，然后有目的的去发现有价值的属性）。最终确定，是一个监控数据上报的接口产生的NioChannel对象。 /openapi/ff/metric/receive是我们的一个接受客户端监控数据上报的接口。考虑到可能因为数据较大从而导致请求读写的时间较久，还是去看了一下Nginx层的日志。发现不存在单个请求的处理时间超过1000ms的情况，所以基本上判断并不是因为长时间占用后释放的情况。再加上我们的Nginx层也没有对Tomcat开启长链接，所以这种长生命周期对象进入到Old区后被释放的可能性就被排除了。大对象排查既然不是长生命周期的，那会不会是大对象呢（Humongous Object）？因为大对象可能会直接进入Old区。Humongous Object: For G1 GC, any object that is more than half a region size is considered a "Humongous object". Such an object is allocated directly in the old generation into "Humongous regions". These Humongous regions are a contiguous set of regions. StartsHumongous marks the start of the contiguous set and ContinuesHumongous marks the continuation of the set. from G1 Doc一句话总结： 如果超过G1回收器划分的堆最小单位Region一半的对象，都认为是大对象，会被放到专门的Humongous Regions
通过查看NioChannel类的信息，我们可以看到实际上这个对象并不是大对象。内部也没有大字符串或者大的数组，即便是遇到了稍大的请求过来，也会因为使用了流从而避免了一次性读取的内存占用。（这一点我贴个关于流读取，JAVA从哪读取，为什么不会占用内存的小文档吧）当然了，最主要的是我们这个接口真的没有那么大的请求体！ 222499 是请求体的大小，约等于217KB，远远没有达到堆1/2 堆Region。nginx access日志33.63.149.6410481 - [24/Jul/2025:15:40:58 +0800] "POST http://openapi-cc.cainiao-inc.com/openapi/ff/metric/receive"200117"-""127.0.0.1:7001""okhttp/4.9.3""-""-""213f954017533428582351009e11ac""222499"
如果你觉得缺乏支撑力，那索性我就给你FullGC一下，让你看看Humongous Region的回收情况。在YGC回收之后，可以看到Old + Hug区域的数量是66和2。使用FGC之后Old区域回收明显，虽然大对象区域也有回收，但是比较明确的是大对象总体也不超过32MB。所以，也侧面验证老年代的NioChannel并不是大对象！使用FullGC之后 回收明显的是Old Region提前晋升排查对象提前晋升到Old区可能发生在Young/Mixed GC的时候，当动态分配的Survivor区域的空间小于本次GC要晋升的对象所需空间总和时，就会将部分未“年满”的对象直接放到Old区。表现上就是Survivor Regions的数量减少，同时Old Regions的数量增加。当然最可靠的方式是增加gc+age*=trace到 SERVICE_OPTS="${SERVICE_OPTS} -Xlog:gc*,gc+age=trace:${MIDDLEWARE_LOGS}/gc.log:time"来记录每次GC的时候，Survivor区晋升对象的年龄段信息来判断。例如下面，survivor预期的大小是163577856字节（156M），想要晋升到老年代的话年龄要大于1就可以。所以Old区域从73->75增加2个Regions。[2025-07-27T09:21:23.641+0800] GC(530) Desired survivor size 163577856 bytes, new threshold 1 (max threshold 15)GC时打印每个年龄的内容大小[2025-07-27T09:21:23.641+0800] GC(530) Pause Young(Normal)(G1 Evacuation Pause)
[2025-07-27T09:21:23.641+0800] GC(530) Using 4 workers of 4 for evacuation
[2025-07-27T09:21:23.641+0800] GC(530) Desired survivor size 163577856 bytes, new threshold 1 (max threshold 15)
[2025-07-27T09:21:23.649+0800] GC(530) Pre Evacuate Collection Set: 0.2ms
[2025-07-27T09:21:23.649+0800] GC(530) Merge Heap Roots: 0.2ms
[2025-07-27T09:21:23.649+0800] GC(530) Evacuate Collection Set: 6.5ms
[2025-07-27T09:21:23.649+0800] GC(530) Post Evacuate Collection Set: 0.9ms
[2025-07-27T09:21:23.649+0800] GC(530) Other: 0.4ms
[2025-07-27T09:21:23.649+0800] GC(530) Age table with threshold 1 (max threshold 15)
[2025-07-27T09:21:23.649+0800] GC(530) - age 1: 5675240 bytes, 5675240 total
[2025-07-27T09:21:23.649+0800] GC(530) Eden regions: 286->0(305)
[2025-07-27T09:21:23.649+0800] GC(530) Survivor regions: 21->2(39)
[2025-07-27T09:21:23.649+0800] GC(530) Old regions: 73->75
[2025-07-27T09:21:23.649+0800] GC(530) Archive regions: 2->2
[2025-07-27T09:21:23.649+0800] GC(530) Humongous regions: 6->6
[2025-07-27T09:21:23.649+0800] GC(530) Metaspace: 325786K(328256K)->325786K(328256K) NonClass: 284608K(285760K)->284608K(285760K) Class: 41177K(42496K)->41177K(42496K)
[2025-07-27T09:21:23.649+0800] GC(530) Pause Young(Normal)(G1 Evacuation Pause) 3094M->664M(4096M) 8.089ms
[2025-07-27T09:21:23.649+0800] GC(530) User=0.02s Sys=0.01s Real=0.01s
正常的晋升阀值应该是15，也就是Age table with threshold 15 （max threshold 15），例如下面的记录：正常晋升的GC日志[2025-07-25T17:56:48.616+0800] GC(82) Pause Young(Normal)(G1 Evacuation Pause)
[2025-07-25T17:56:48.616+0800] GC(82) Using 4 workers of 4 for evacuation
[2025-07-25T17:56:48.617+0800] GC(82) Desired survivor size 192937984 bytes, new threshold 15 (max threshold 15)
[2025-07-25T17:56:48.629+0800] GC(82) Pre Evacuate Collection Set: 0.7ms
[2025-07-25T17:56:48.629+0800] GC(82) Merge Heap Roots: 0.3ms
[2025-07-25T17:56:48.629+0800] GC(82) Evacuate Collection Set: 9.2ms
[2025-07-25T17:56:48.629+0800] GC(82) Post Evacuate Collection Set: 2.3ms
[2025-07-25T17:56:48.629+0800] GC(82) Other: 0.4ms
[2025-07-25T17:56:48.629+0800] GC(82) Age table with threshold 15 (max threshold 15)
[2025-07-25T17:56:48.629+0800] GC(82) - age 1: 7050184 bytes, 7050184 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 2: 231944 bytes, 7282128 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 3: 435344 bytes, 7717472 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 4: 4397464 bytes, 12114936 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 5: 2907264 bytes, 15022200 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 6: 43528 bytes, 15065728 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 7: 323752 bytes, 15389480 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 8: 2450560 bytes, 17840040 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 9: 96400 bytes, 17936440 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 10: 161992 bytes, 18098432 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 11: 139088 bytes, 18237520 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 12: 70312 bytes, 18307832 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 13: 1476384 bytes, 19784216 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 14: 79144 bytes, 19863360 total
[2025-07-25T17:56:48.629+0800] GC(82) - age 15: 31632 bytes, 19894992 total
[2025-07-25T17:56:48.629+0800] GC(82) Eden regions: 182->0(182)
[2025-07-25T17:56:48.629+0800] GC(82) Survivor regions: 2->2(23)
[2025-07-25T17:56:48.629+0800] GC(82) Old regions: 18->18
[2025-07-25T17:56:48.629+0800] GC(82) Archive regions: 2->2
[2025-07-25T17:56:48.629+0800] GC(82) Humongous regions: 0->0
[2025-07-25T17:56:48.629+0800] GC(82) Metaspace: 332418K(335360K)->332418K(335360K) NonClass: 290266K(291648K)->290266K(291648K) Class: 42151K(43712K)->42151K(43712K)
[2025-07-25T17:56:48.629+0800] GC(82) Pause Young(Normal)(G1 Evacuation Pause) 3227M->313M(4928M) 12.959ms
[2025-07-25T17:56:48.629+0800] GC(82) User=0.02s Sys=0.02s Real=0.02s
既然出现了问题，我们主要还是要解决问题。要么解决这些对象被放进Old区域的问题，要么就是放进去能够被及时回收。Old区域回收对于老年代的对象回收，G1引入了两种可回收的机制，一种是Mixed GC、另一种则是耳熟能详的FullGC。Mixed GC就是能够具备YoungGC和FullGC的两者共同作用的，可以对新生代和老年代同时进行对象回收。并且呢，MixedGC的回收不会产生STW的长停止。这一点是因为在G1(Garbage First)的机制中，将堆划分为更多小的Regions，这样可以比较灵活的对不同区域的garbage和live object做复制及统一清理。MixedGC对于MixedGC的触发可以有两种方式：方式一：自适应模式，必须JDK10+，让JVM的垃圾回收器自行决定触发IHOP的时机-XX:+G1UseAdaptiveIHOP ；方式二：手动设置老年代已用空间占总堆空间的比例时启动存活对象的并发标记(IHOP)，帮助下次GC的时候更快的清理出不可达的对象，-XX:InitiatingHeapOccupancyPercent=40 默认值为45。标记之后，不出意外的情况下将会触发Mixed GC，在sunfire中还是以YongGC的方式展示的，但是可以在gc.log中看到Pause Young (Mixed)。
这个InitiatingHeapOccupancyPercent的值设置不宜较大也不宜过小，较大可能导致FullGC的次数较多，而Mixed次数较少，从而导致STW的时长较长。过小的会就又会频繁的依法标记清理行为，GC的负担较重，吞吐量下降。就我们系统而言，堆空间大小为5g，IHOP=40%，所以要老年代在2g左右的时候才会触发。然而实际只有1.2g，所以一直未触发MixedG。为了能够触发Old中提前晋升对象的清理，我们将堆空间做了压缩，修改为4g，regions=8m，为了触发MixedGC所以设置IHOP=20%，在785次GC的时候，Old Regions使用到95个Regions、Humongous用到了6个Regions，整个老年代也就是104*8 = 832m，约占堆空间20.3%>20%。786次GC触发了MixedGC 的标记，787做了Mixed准备，788完成清理并让Old区域得到了有效的空间释放。GC详情$cat gc.log|grep 'GC(785)' -A 100
[2025-07-27T18:34:45.406+0800] GC(785) Pause Young(Concurrent Start)(G1 Evacuation Pause)
[2025-07-27T18:34:45.406+0800] GC(785) Using 4 workers of 4 for evacuation
[2025-07-27T18:34:45.407+0800] GC(785) Desired survivor size 163577856 bytes, new threshold 15 (max threshold 15)
[2025-07-27T18:34:45.414+0800] GC(785) Pre Evacuate Collection Set: 0.4ms
[2025-07-27T18:34:45.414+0800] GC(785) Merge Heap Roots: 0.2ms
[2025-07-27T18:34:45.414+0800] GC(785) Evacuate Collection Set: 5.2ms
[2025-07-27T18:34:45.414+0800] GC(785) Post Evacuate Collection Set: 1.4ms
[2025-07-27T18:34:45.414+0800] GC(785) Other: 0.4ms
[2025-07-27T18:34:45.414+0800] GC(785) Age table with threshold 15 (max threshold 15)
[2025-07-27T18:34:45.414+0800] GC(785) - age 1: 7024296 bytes, 7024296 total
[2025-07-27T18:34:45.414+0800] GC(785) - age 2: 457032 bytes, 7481328 total
[2025-07-27T18:34:45.414+0800] GC(785) Eden regions: 305->0(305)
[2025-07-27T18:34:45.414+0800] GC(785) Survivor regions: 2->2(39)
[2025-07-27T18:34:45.414+0800] GC(785) Old regions: 95->95
[2025-07-27T18:34:45.414+0800] GC(785) Archive regions: 2->2
[2025-07-27T18:34:45.414+0800] GC(785) Humongous regions: 6->6
[2025-07-27T18:34:45.414+0800] GC(785) Metaspace: 328827K(331392K)->328827K(331392K) NonClass: 287287K(288512K)->287287K(288512K) Class: 41539K(42880K)->41539K(42880K)
[2025-07-27T18:34:45.414+0800] GC(785) Pause Young(Concurrent Start)(G1 Evacuation Pause) 3267M->823M(4096M) 7.558ms
[2025-07-27T18:34:45.414+0800] GC(785) User=0.02s Sys=0.01s Real=0.01s
[2025-07-27T18:34:45.414+0800] GC(786) Concurrent Mark Cycle
[2025-07-27T18:34:45.414+0800] GC(786) Concurrent Clear Claimed Marks
[2025-07-27T18:34:45.414+0800] GC(786) Concurrent Clear Claimed Marks 0.107ms
[2025-07-27T18:34:45.414+0800] GC(786) Concurrent Scan Root Regions
[2025-07-27T18:34:45.423+0800] GC(786) Concurrent Scan Root Regions 8.377ms
[2025-07-27T18:34:45.423+0800] GC(786) Concurrent Mark
[2025-07-27T18:34:45.423+0800] GC(786) Concurrent Mark From Roots
[2025-07-27T18:34:45.423+0800] GC(786) Using 1 workers of 1for marking
[2025-07-27T18:34:45.627+0800] GC(786) Concurrent Mark From Roots 204.859ms
[2025-07-27T18:34:45.627+0800] GC(786) Concurrent Preclean
[2025-07-27T18:34:45.630+0800] GC(786) Concurrent Preclean 2.474ms
[2025-07-27T18:34:45.630+0800] GC(786) Pause Remark
[2025-07-27T18:34:45.723+0800] GC(786) Pause Remark 830M->766M(4096M) 92.215ms
[2025-07-27T18:34:45.723+0800] GC(786) User=0.14s Sys=0.18s Real=0.09s
[2025-07-27T18:34:45.723+0800] GC(786) Concurrent Mark 300.239ms
[2025-07-27T18:34:45.723+0800] GC(786) Concurrent Rebuild Remembered Sets
[2025-07-27T18:34:45.837+0800] GC(786) Concurrent Rebuild Remembered Sets 113.930ms
[2025-07-27T18:34:45.851+0800] GC(786) Pause Cleanup
[2025-07-27T18:34:45.851+0800] GC(786) Pause Cleanup 769M->769M(4096M) 0.216ms
[2025-07-27T18:34:45.851+0800] GC(786) User=0.00s Sys=0.00s Real=0.00s
[2025-07-27T18:34:45.851+0800] GC(786) Concurrent Cleanup for Next Mark
[2025-07-27T18:34:45.871+0800] GC(786) Concurrent Cleanup for Next Mark 19.789ms
[2025-07-27T18:34:45.871+0800] GC(786) Concurrent Mark Cycle 456.946ms
[2025-07-27T18:37:22.521+0800] GC(787) Pause Young (Prepare Mixed) (G1 Evacuation Pause)
[2025-07-27T18:37:22.521+0800] GC(787) Using 4 workers of 4for evacuation
[2025-07-27T18:37:22.522+0800] GC(787) Desired survivor size 163577856 bytes, new threshold 15 (max threshold 15)
[2025-07-27T18:37:22.532+0800] GC(787) Pre Evacuate Collection Set: 0.3ms
[2025-07-27T18:37:22.532+0800] GC(787) Merge Heap Roots: 0.3ms
[2025-07-27T18:37:22.532+0800] GC(787) Evacuate Collection Set: 7.9ms
[2025-07-27T18:37:22.532+0800] GC(787) Post Evacuate Collection Set: 1.6ms
[2025-07-27T18:37:22.532+0800] GC(787) Other: 0.4ms
[2025-07-27T18:37:22.532+0800] GC(787) Age table with threshold 15 (max threshold 15)
[2025-07-27T18:37:22.532+0800] GC(787) - age 1: 6433880 bytes, 6433880 total
[2025-07-27T18:37:22.532+0800] GC(787) - age 2: 152848 bytes, 6586728 total
[2025-07-27T18:37:22.532+0800] GC(787) - age 3: 288504 bytes, 6875232 total
[2025-07-27T18:37:22.532+0800] GC(787) Eden regions: 305->0(24)
[2025-07-27T18:37:22.532+0800] GC(787) Survivor regions: 2->1(39)
[2025-07-27T18:37:22.532+0800] GC(787) Old regions: 93->93
[2025-07-27T18:37:22.532+0800] GC(787) Archive regions: 2->2
[2025-07-27T18:37:22.532+0800] GC(787) Humongous regions: 0->0
[2025-07-27T18:37:22.532+0800] GC(787) Metaspace: 327724K(331328K)->327724K(331328K) NonClass: 286413K(288448K)->286413K(288448K) Class: 41310K(42880K)->41310K(42880K)
[2025-07-27T18:37:22.532+0800] GC(787) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 3199M->755M(4096M) 10.281ms
[2025-07-27T18:37:22.532+0800] GC(787) User=0.03s Sys=0.01s Real=0.01s
[2025-07-27T18:37:34.704+0800] GC(788) Pause Young (Mixed) (G1 Evacuation Pause)
[2025-07-27T18:37:34.704+0800] GC(788) Using 4 workers of 4for evacuation
[2025-07-27T18:37:34.704+0800] GC(788) Desired survivor size 16777216 bytes, new threshold 15 (max threshold 15)
[2025-07-27T18:37:34.711+0800] GC(788) Pre Evacuate Collection Set: 0.2ms
[2025-07-27T18:37:34.711+0800] GC(788) Merge Heap Roots: 0.2ms
[2025-07-27T18:37:34.711+0800] GC(788) Evacuate Collection Set: 5.2ms
[2025-07-27T18:37:34.711+0800] GC(788) Post Evacuate Collection Set: 0.9ms
[2025-07-27T18:37:34.711+0800] GC(788) Other: 0.2ms
[2025-07-27T18:37:34.711+0800] GC(788) Age table with threshold 15 (max threshold 15)
[2025-07-27T18:37:34.711+0800] GC(788) - age 1: 8877768 bytes, 8877768 total
[2025-07-27T18:37:34.711+0800] GC(788) - age 2: 3662768 bytes, 12540536 total
[2025-07-27T18:37:34.711+0800] GC(788) - age 3: 151272 bytes, 12691808 total
[2025-07-27T18:37:34.711+0800] GC(788) - age 4: 285584 bytes, 12977392 total
[2025-07-27T18:37:34.711+0800] GC(788) Eden regions: 24->0(305)
[2025-07-27T18:37:34.711+0800] GC(788) Survivor regions: 1->2(4)
[2025-07-27T18:37:34.711+0800] GC(788) Old regions: 93->53
[2025-07-27T18:37:34.711+0800] GC(788) Archive regions: 2->2
[2025-07-27T18:37:34.711+0800] GC(788) Humongous regions: 0->0
[2025-07-27T18:37:34.711+0800] GC(788) Metaspace: 327724K(331328K)->327724K(331328K) NonClass: 286413K(288448K)->286413K(288448K) Class: 41310K(42880K)->41310K(42880K)
[2025-07-27T18:37:34.711+0800] GC(788) Pause Young (Mixed) (G1 Evacuation Pause) 947M->441M(4096M) 6.822ms
[2025-07-27T18:37:34.711+0800] GC(788) User=0.02s Sys=0.01s Real=0.01s
核心的释放老年代的事在下面的日志中完成的，总共释放了大约500M的老年代。其实还有一个细节就是关于Humongous Regions 从6清理到0的过程并没有显式的打印出来。这是因为MixedGC相对标记清理来说是少有延迟的，在786次的 Pause Preclean的时候，已经将部分Regions做了回收。 [2025-07-27T18:34:45.723+0800] GC(786) Pause Remark 830M->766M(4096M) 92.215ms[2025-07-27T18:37:34.711+0800] GC(788) Pause Young (Mixed) (G1 Evacuation Pause) 947M->441M(4096M) 6.822ms-XX:SurvivorRatio=10 就可能引起Survivor区域分配不足的问题。直接调整-XX:SurvivorRatio=8 或者更低，可以增加Survivor的空间大小。不过值得注意的是，在JDK8之后，SurvivorRatio在运行过程中的作用基本上被取代。关于新生代的各个详细区域的Region分配，是根据设置的最大GC暂停上限、历史晋升/存活率、Region拷贝成本等，动态估算此次YGC/Mixed GC应征收多少region。所以这个作用基本上是心理安慰！减少NioChannel对象的产生除了Old区进行清理之外，还是要究其根本让这种提前晋升的对象数量减少。从dump的对象信息中已经确认NioChannel的对象比较多，并且大部分是不可达的。NioChannel怎么来的那么这个对象产生的逻辑是什么呢？这一点通过Tomcat的源码，我找到了真相。代码来源：org.apache.tomcat.util.net.NioEndpoint#setSocketOptions，一句话来说就是：当NioEndpoint中可用channel不足时，会创建新的NioChannel。Socket链接处理的核心逻辑publicclassNioEndpointextendsAbstractJsseEndpoint<NioChannel,SocketChannel> {
private SynchronizedStack<NioChannel> nioChannels;
@Override
protected boolean setSocketOptions(SocketChannel socket){
NioSocketWrapper socketWrapper = null;
try {
NioChannel channel = null;
if (nioChannels != null) {
channel = nioChannels.pop();
}
if (channel == null) {
SocketBufferHandler bufhandler = new SocketBufferHandler(
socketProperties.getAppReadBufSize(),
socketProperties.getAppWriteBufSize(),
socketProperties.getDirectBuffer());
if (isSSLEnabled()) {
channel = new SecureNioChannel(bufhandler, this);
} else {
channel = new NioChannel(bufhandler);
}
}
NioSocketWrapper newWrapper = new NioSocketWrapper(channel, this);
channel.reset(socket, newWrapper);
returntrue;
} catch (Throwable t) {
returnfalse;
}
}
org.apache.tomcat.util.net.NioEndpoint#nioChannels是一个Tomcat设计复用对象，减少因为SocketChannel数量攀升而导致的临时JVM内存增加的设计之一。通过栈来存放已经使用NioChannel达到循环使用的目的，当然里面还涉及到内部scoketChannel的等属性清理。整个栈在NioEndpoint启动的时候，Tomcat 9.x会进行初始化：size = 128，limit=500。所以也就意味着当某个时刻的socket超过500的时候，会有点超出limit的值，自然就会出现pop结果为null，只能创建临时NioChannel的情况。而恰好！我们的服务端在接受客户端数据上报时，存在QPS峰值>500的情况。服务端QPS统计机器QPS峰值验证猜想所以在就会出现每隔一段时间，创建出了临时的NioChannel对象，并且因为幸存区不足直接晋升到老年代的情况。关键这还是一个不断叠加的过程，表达出来如下面的表格一样：可能并不是所有新增的NioChannel都会提前晋升，但是大部分会。峰值前后的服务端口 TCP连接数变化峰值前后的NioChannel数量变化解决方案解决方案一：调整复用对象数量(已经采用)到目前为止已经明确了问题产生原因，也通过调节MixedGC标记触发的参数和堆空间总大小完成了NioChannel的回收。那么Tomcat的这个Endpoint中的nioChannels栈能不能适当的调整一下呢？ 稍微比QPS高一点就可以。想要修改的话需要保证在NioEndpoint启动之前做好SocketProperties的默认值覆盖，org.apache.tomcat.util.net.SocketProperties。Properties that can be set in the <Connector> element in server.xml. All properties are prefixed with "socket." and are currently only working for the Nio connector
配置socket相关属性@Configuration
publicclassTomcatPropertiesConfigimplementsWebServerFactoryCustomizer<TomcatServletWebServerFactory> {
@Override
publicvoidcustomize(TomcatServletWebServerFactory factory){
factory.addConnectorCustomizers((Connector connector) -> {
ProtocolHandler protocolHandler = connector.getProtocolHandler();
if (protocolHandler instanceof AbstractProtocol) {
connector.setAttribute("socket.bufferPool", 1024);
}
});
}
}
果然设置了NioChannels为1024个复用对象之后，经历多次QPS峰值周期，并没有出现临时NioChannel进入到老年代或者不符合存活条件的NioChannel了。数量稳定解决方案二：集群扩容(未采用)最直接的解决方式就是集群扩容了，但是我觉得现在直接扩容是不太明智的选择。集群内的机器在相同时刻基本上流量均衡的，除了NioChannel数量有些超出想象之外，CPU使用率和内存使用率均未充分使用。所以不能一味的为了满足某个时刻的流量而随心所欲的借助集群容量来应对。解决方案三：分散数据上报(已经采用)另一个问题就是请求较为集中导致的高QPS问题！从监控上可以明显地看到存在超高峰的流量不均问题。这种情况应该采用“削峰填谷”的方式化解瞬时流量，活着直接集中上报的问题。从上图上面看，的确是集中在整点十分钟会出现峰值。通过排查SDK将上报的逻辑调整为，按照各个客户端IP分时触发上报。下面是我们SDK上报数据的逻辑，为了减少采集数据占用内存的空间，所以按照每10分钟进行作为一个数据集，并且存放到size为2的队列中缓存。当第3个数据集出来时（其实就是准点十分），就会因为有过期数据集而触发瞬间上报的情况。未分时上报所以为了能够将流量进行分散，我们按照IP纬度做个延迟数据上报。最高延迟30s的情况下，理论上可以将QPS缩小十倍。增加延迟时间上报概括本次内存达到90%的原因就是：大批客户端在相同时间对服务端发起Http请求，导致服务端的Tomcat中的Socket数量剧增，原本默认500的复用对象缓存池不足，所以创建了大量NioChannel对象。并且在如此悬殊的流量洪峰下，GC未能及时清理出幸存区导致临时对象提前晋升到老年代，造成老年代膨胀。但是总堆设置的较大，老年代的内存/总堆内存又未能触发MixedGC和FullGC，最终出现了老年代周期性增加，总内存使用达到容器90%的问题。老年代增加明显，无回收现象总体看下来，会觉得内存占用较大并且没有被回收，找到可以的对象之后，应该就会知道是因为Socket连接较多导致的呀。为什么不先去看看QPS或者连接数之类的呢。这里实际上有点尴尬了，因为应用中间件中间中的Nginx和我重新配置的Nginx流量QPS相差甚大！这也是导致无法快速定位到问题的其中一个原因。但是实际上这个QPS峰值周期是应该得到重视的！后面还是去看看流量监控不准确的问题。这个是Nginx监控，与600多的QPS相差较大而对于在线连接数这个指标，虽然偶尔到2000，但是不足以作为支撑NioChannel被创建为临时对象并且提前晋升的证据。还需要一点点向内剖析，直到所有的依据坐实。所以，实际上在整个运维工具使用上是有帮助的，从前往后去发掘线索总开始困难的，但是从后向前推导出线索价值总是那么明晰。确保客观数据的准确性，要善于使用运维工具。这个SDK实际上是在初期设计和开发过程中已经做过多次的压测，整个客户端的性能基本问题不大。对于服务端而言，也没有明显的RT增加，所以一直没有当作问题来看待。虽然这次直接通过调整内存就已经实现了MixedGC对老年代的回收，不足以产生故障。但是究其根本之后，还是觉得这个问题在客户端比服务端多几十上百倍的时候，就应该要考虑流量的分散。阅读原文
跳转微信打开
