reservedcodecachesize

背景闲鱼的一个关键应用依托于类目系统的富客户端(以下简称类目客户端)，旨在为闲鱼商品领域的其他应用提供各种商品类目和属性数据(以下简称CPV数据)查询服务。

每天早上，当应用所依赖的class rich client在新旧版本数据包之间切换时，应用提供的服务抖动非常明显，表现为大量的接口超时(100ms–>；3-5s)，服务成功率明显下降(100%-& gt；~92%)，RPC线程池中的活动线程数增加(50->；~100)，抖动最长可持续20s，影响产品发布、产品详情页等依赖CPV数据的关键业务场景。并且抖动发生在夜间，时间点不固定，发生抖动时开发生很难注意到，影响面不可控，需要排查并彻底解决这个问题。

排查过程

其实这是一个表象简单的问题，但根源隐藏很深。笔者在调查过程中也走了一些弯路，写出来供读者参考。

堆空间不够？

结构化应用程序行最初使用4C8G标准规范容器，并分配4G内存作为堆内存，截取了一些JVM启动参数如下:

-Xms4g-Xmx4g-XX:MetaspaceSize = 512m-XX:MaxMetaspaceSize = 512m-XX:+UnlockExperimentalVMOptions-XX:G1 maxnewsizepercent = 65-XX:+use G1 GC-XX:initiating h eapcoccupcypercent = 55-XX:G1 heapregionsize = 16m-XX:G1 newsizepercent = 25-XX:MaxGCPauseMillis = 120-XX:+parallelrefproceabled-XX:MaxDirectMemorySize = 1g-1

undefined

由于本人先前在排查类似的FGC问题时，经常能在Heap Dump的支配树中看到类目客户端相关对象长期占据高位，是内存占用大户。所以难免主观印象先入为主，初步以为是切换版本的过程中，在老版本数据包卸载之前，可能会存在短暂的堆内空间占用double的情况。未定义因为我以前查过类似的FGC问题，经常可以看到类别客户端的相关对象在堆转储的优势树中长时间占据很高的位置，这是一个很大的内存用户。所以难免主观印象先入为主。最初认为在切换版本的过程中，在旧版本的数据包卸载之前，可能会出现堆中空之间占用double的短暂情况。

启动参数配置的Eden面积下限为25%。可能有老居民职业+新数据包>；4G的形势触发了FGC。

因此，由于空之间的空间不可避免地会占用一倍，而旧时代驻留的空之间的空间在短时间内不会显著下降，因此必须固定一个下限值，以解决之前该应用中出现混合GC时伊甸园区域异常收缩导致的YGC异常，而这只能通过扩展容器内存规范来实现，看是否可以缓解。

所以应用容器基线升级到4C16G，设置在16G容器环境，10G内存分配给heap 空，逐步升级online service的容器规范。

结果花了两天时间升级了线上的大部分容器，查看监控后发现规格大的容器没有FGC，而且得益于巨大的堆内存(10G)，从GC监控中甚至看不到切包动作。但是RPC的成功率还是会下降(100%->；百分之九十七)，RPC线程池中的线程数量仍然略有增加(50–>；~71)。

由此可见，FGC并不是造成切包抖动的核心原因，其背后还有更深层次的原因需要探究。

容器CPU高触发自适应限流？

再次询问受影响的业务方，通过下游应用的日志找到数据包抖动的时间点，出现了很多哨兵限流日志。但是在结构化应用中，接口没有主动配置限流，只有组内的sentinel中间件可能因为在某个时间点检测到CPU利用率过高(超过80%)而自动执行限流策略。

Sentinel是集团内部的流量控制中间件，可以从限流、流量整形、熔丝退化、系统自适应保护、热点保护等多个维度帮助业务保证微业务的稳定性。

登录发生限流的服务商对应的机器，我确实看到了限流日志。

$ cat CPU-sampling . log . 1 | grep ” 2022-05-1903:57 ” | grep-v ” 0.0 “
2022-05-1903:57:12.435 | | | |应用程序名称| CPU采样| 0。

但从应用监控的角度来看，机器此刻的CPU利用率只有20%多(以100%为单位)。而sentinel的cpu采样日志只grep出一个满CPU的日志。根据限流中间件20ms的采样频率，说明这只是CPU尖峰，应该不会造成大规模影响。笔者其实对限流导致RPC成功率下降有点怀疑，认为应该不是这样的问题。

无论如何，最简单的验证方法就是找一台16G内存在线改的机器，将sentinel中间件设置为空运行模式，只记录日志，不进行实际的限流操作。看接口成功率会不会下降。按照上面的推理，最长的CPU尖峰不会超过40ms，即使CPU满负荷发挥40ms，也不会导致界面超时几秒。

结果到了晚上，接口的成功率还是下降了，出现了几秒钟的超时。

源码窥密，探究类目客户端切包过程中具体动作

在发现单纯升级集装箱规格无法解决包装切割抖动问题后，作者改写了手头已掌握的线索:

1.FGC不是切包抖动的核心原因，而是升级容器花钱后得出的结论。那么，如果我们不花这笔钱，仅仅从监测就能得出结论吗？其实是有可能的。如果目前的在线容器规格完全不能满足切包所需的内存消耗，理论上集群中的每台机器在切包时都会有FGC，但实际上成套在切包时产生的FGC量并不多，最多20次左右，只有1/6的机器有FGC，其余机器只有YGC略有增加，然后迅速回到正常水位。即使YGC量增加，也只需要YGC从每分钟70ms到200ms，不需要大量接口超时。

2.sentinel检测到CPU尖峰，自动实施限流，确实拉低了服务成功率。但即使关闭了限流，几秒钟后接口依然会超时，说明限流并不是接口成功率下降的主要原因。

3.类别客户询问类别数据是存储在磁盘中、堆中还是堆外内存中，有不同的意见。但是，不同的存储方式，最终可能会得出完全不同的结论。为了找出这个问题，最准确的方法是读取类别客户端切割包的源代码。所以作者花了一些时间，

类目服务切包流程整个切包过程，都是在类目客户端自带的netty ChannelHandler的回调线程中单线程完成的，没有多线程并行加载的动作。在初始化分类服务入口时，虽然有很多建立索引等看似重新计算的动作，但理论上CPU最多会打到100%(一个核心)，不会出现因为底层是单线程而打到400%的情况。在凌晨，结构化应用的CPU利用率很低，不到10%。理论上，削减套餐和服务不会导致CPU满负荷。它不太可能导致几秒钟的服务无响应。

随着对切包和错误发生的时间和日志信息的进一步梳理，一个更奇怪的现象浮出水面。

反常现象：切包完毕后接口开始超时

观察以下完整链接日志:

Com。Taobao . idle . modulet . itemkgraphserviceapi @ getspupublishsearchv 3 ~ M接口超时8s。注意，这个错误发生在2022年5月24日01: 38: 19.523。

平时这个接口RT在400m左右，底层使用线程池并行切换各种搜索服务，设置1s总超时，大量try catch包，基本不会报错。

再看一下这个时间点附近的分类树日志:

如你所见，在01:38:00，类别数据已经被切换。01:38:14连旧文件都删了。切包结束。

然而，在01:38:27，类别服务的一个日志记录程序从KGRaphCommonFixed线程工厂-10-Thread-95线程打印出两行日志:

2022-05-24 01:38:27.715[kgraphconfixedthreadfactory-10-thread-95][]警告类别服务记录器-加载STD _ category _ property _ value store finished的缓存，耗时7820ms，缓存了278个块。
2022-05-24 01:38:31.236[kgraphconfixedthreadfactory-10-thread-95][]警告类别服务记录器-加载STD _ category _ property _ value存储的缓存已完成。它需要11341毫秒，缓存了109个块。而这个线程池，是运行getSpuPublishSearchV3接口的底层来切换各种搜索的执行线程，代码为异步执行的未来设置1s超时。如果执行超过一秒，接口服务的代码将不再等待，而是直接执行。

更巧的是，从01:38:19到01:38:27是8秒，与上面监测到的超时相吻合。看到这里，问题似乎变得更复杂了。

1.刚才我们提到了在category client的netty ChannelHandler线程中进行了切包。现在怎么能跑到业务线程池甚至挂起接口呢？

2.为什么所有的分类服务都运行在其他线程池上，而线程池超时设置为1s？为什么接口上有8s超时？

拨云见雾，逐个击破

其实回答问题1并不难。因为日志已经打出来了，所以只需要全局搜索Load的缓存，就可以找到类别树日志唯一的地方，然后反向找到调用栈。你会发现类别属性和类别属性值这两个存储是懒加载的。只有在切包之后，第一个读取类别的属性和属性值的请求，才会触发通过mmap将存储文件映射到Ja进程的一个连续虚拟地址的动作，将数据从磁盘读入内存。

核心代码:

MappedByteBuffer mapped buffer = store file . getfile channel()。地图(地图模式。READ_ONLY，segmentPosition，segment size)；//创建mmap映射
mapped buffer . load()；//将数据读入内存
buffer buffer = fixed byte buffer。wrap(映射缓冲区)；
this . buffercachearray[t]= new buffer cache(buffer，((t == 0)？meta.getHeaderSize() : 0)、blockCountThisSegment、meta . get blocksize())；
for (int i = ((t == 0)？0:blockid flags[t-1])；我& ltblockid flags[t]；i++){
getReadBlock(I)；//提前创建block kid-> block buffer的映射
}所以加载后的日志自然是在业务线程池中打出来的。

Page Fault的“威力”

问题2很难回答。因为有一个非常明显的矛盾:这个商店加载在业务线程池，所有未来只等1s。1s没打完，马上就回来了，不可能拿8s。而且机器已经是16G的集装箱了，也没有FGC造成的STW。那么只有进程级挂起会影响多线程。

为了确认是否存在进程挂起，作者再次查看了自适应cpu采样日志。不看不知道，一看吓一跳:

20ms采样一次CPU并记录日志的线程也被hang阻塞！直到01:38:27才恢复日志打印。而且这个时间正好是存储在加载中的时间，也和接口超时一致。

基本只有一种可能，就是第一次读取mmap映射虚拟地址段的数据时，因为数据在硬盘，而不在内存，所以会触发页面错误，使得JVM进程陷入内核状态，执行从磁盘加载数据到内存的页面错误处理程序，导致进程挂起，直到返回用户状态。

参考理解Linux内核的9.4.2节来处理地址空间中的错误地址。有一段话是这样写的:

如果handle_mm_fault()函数成功地为进程分配了一个新的页面帧，它将返回VM_FAULT_MINOR或VM_FAULT_MAJOR。值VM_FAULT_MINOR表示在不阻塞当前进程的情况下已经处理了页面错误；这种页面错误称为小错误。

值VM_FAULT_MAJOR表示页面错误迫使当前进程休眠(很可能是因为在用从磁盘读取的数据填充分配给该进程的页面帧时花费了时间)；当前进程的页面错误称为主要错误。

该函数还可以返回VM_FAULT_OOM(内存不足)或VM_FAULT_SIGBUS(每隔一个错误)。

注意加粗的部分。在处理内存中的页面错误事件时，如果出现了重大的页面错误，那么这个页面错误会强制当前进程休眠(基本上是在需要将数据从磁盘读取到进程地址空)内的页面块的耗时场景中)。

再次查看MappedByteBuffer#load()方法Jadoc:

如您所见，Jadoc声明:调用此方法可能会导致一些页面错误和I/O操作发生。调用此方法可能会产生一些页面错误。

那么只要确认JVM进程在加载存储的过程中产生了大量的重大页面错误，就可以解释清楚为什么会出现线程交叉挂起的情况。

这里我主要用两个命令:pmap和sar。

Pmap可以显示一个进程的所有连续地址空。通过查看addresses 空和RSS列的值之间的文件引用，可以显示当前连续内存空中有多少页被进程引用。

在日常机器上重现场景时，可以看到当前进程在执行load store方法之前，并没有引用任何相关类别文件的虚拟地址空。

调用查询属性和属性值的方法后，可以看到

加载类别树的属性和属性值存储，RSS value == KBytes，表示整个文件已经读入内存。

另一个重要的抓手是sar命令。Sar命令可以以指定的采样率对当前操作系统的页面错误发生指数进行采样。

可以看到，在initCache过程中，大量的主要页面故障被触发，同时，作者连接到服务器的Arthas命令行也挂起而没有任何响应。进一步验证了上述情况。

Arthas的命令行底层是termd库，用纯Ja实现。而Arthas是以ja代理的形式附着在目标JVM上的。如果阿尔萨斯的控制台输入的命令没有回音，那么基本上只有一种可能，整个JVM进程会挂死，这进一步验证了前面提到的进程落入内核模式的假设。

那为什么杭停留了几秒钟？通过测量联机容器的IO速度，发现容器的磁盘读写速度在100MB左右，而类别属性值的存储文件非常大，达到1.7G g..加载这个文件一次是非常耗时的。

至此，我们终于可以得出结论了。

结论

结构化应用客户端晚上推送包在新旧数据包之间切换后，存储类别属性和属性值的数据不会立即加载到内存中。会等到第一个查询类别属性和属性值的请求来了，才会偷懒加载数据到内存。因为category属性值存储非常大，达到了1.7 g .在将1.7G数据整体加载到内存的过程中，触发了大量的主页面错误，导致进程进入内核状态处理缺页异常。但由于服务容器IO性能不佳，完全读取文件非常耗时，最终导致Ja进程挂起十几秒的现象。

最终解法

带着疑问问分类服务相关的同学，他们的建议是升级到最新版本的客户端。作者比较了新旧版本的客户端代码，主要有两个改进。

1.在切割包之前，您将加载一个存储，而不是等到请求到来。

2.加载存储时，不是一口气加载整个文件，而是把文件切成64M的小块，每次加载64M，然后睡一会儿。然后继续加载下一个块，避免进程长时间处于内核状态，因一次性加载超大文件块而无法向外界提供服务。

回过头来思考上面提出的一些问题。既然接口超时主要是加载大文件导致的，那么16G容器有必要抬高吗？

我觉得还是有必要的。原因有二。

1.现在新品类客户端会先加载一个store，然后再剪切版本，释放旧的包资源(包括虚拟地址空)。虽然存储在堆外内存中，但它仍然需要占用进程的地址空，实际上它仍然需要将数据读入内存。所以在切包的过程中，从整个Ja流程来看，store空之间确实存在双重占用。目前一个类目存储1.7G左右，两个3.4G，还有一个4G 空分区到JVM堆。内存还剩不到1G空，8G容器的内存非常紧张，很容易导致在切包过程中加载新店时容器OOM被杀。

2.虽然store数据都存储在堆外，但是store的一些索引对象和元数据仍然存储在堆内，大约占用6-700M空的堆。无论是新版还是旧版的分类客户端，都是在截包之前构建索引。因此，在构建新的包索引时，峰值也会产生两倍的堆内空占用率，并且很容易因堆内存不足而产生YGC甚至FGC。

总结

一个看起来非常像GC的接口超时，但是在底部有一个更深层次的原因。通过这个案例，也提醒我们，作为技术人，无论外表多么明显，与我们之前遇到的场景多么相似，都需要避免被所谓的经验蒙蔽，先入为主的坏习惯。大胆推断，谨慎论证。多问为什么，就能一步步接近真相。