一个夜间接口超时解决流程

背景闲鱼的一个关键应用依赖于类目系统的富客户端（以下简称类目客户端），旨在为商品领域的其他应用提供各种商品类目和属性。闲鱼数据（以下简称CPV数据）查询服务。每天早上，当应用所依赖的类别富客户端在新旧版本数据包之间切换时，应用提供的服务抖动非常明显，表现为大量的接口超时（耗时100ms）->3-5s)，且服务成功率明显下降(100%->~92%)，RPC线程池活跃线程数增加(50->~100)，抖动可以持续上去到20s，影响依赖CPV数据的关键业务场景，如商品发布、商品详情页；而且抖动发生在晚上，时间点不固定。当出现抖动的时候，开发同学是很难注意的。影响范围相对不可控。因此，有必要对这个问题进行调查和彻底解决。调查过程其实是一个看似很简单，但根源比较深的问题。笔者在调查过程中也走了一些弯路，写在了一起，供读者参考，吸取教训。堆空间不够？结构化应用线原来使用4C8G标准容器，分配4G内存作为堆内存，截获一些JVM启动参数如下：-Xms4g-Xmx4g-XX:MetaspaceSize=512m-XX:MaxMetaspaceSize=512m-XX:+UnlockExperimentalVMOptions-XX:G1MaxNewSizePercent=65-XX:+UseG1GC-XX:InitiatingHeapOccupancyPercent=55-XX:G1HeapRegionSize=16m-XX:G1NewSizePercent=25-XX:MaxGCPauseMillis=120-XX:+ParallelRefProcEnabled-XX:MaxDirectMemorySize=1g-XX:+TraceG1HObjAllocation-XX:ReservedCodeCacheSize=512m-XX:+UseCodeCacheFlushing根据反映界面抖动的同学描述，在界面抖动的时候，FGC发生在请求失败的机器上。undefined因为之前在排查类似FGC问题的时候，经常可以在HeapDump的支配树中看到类别client的相关对象长期占据高位，属于内存占用较大。因此，主观印象难免先入为主。最初以为在切换版本的过程中，在卸载旧版本数据包之前，可能会出现短暂的堆空间占用翻倍的情况。启动参数配置Eden区下限为25%。可能会出现老住户占用+新数据包>4G触发FGC的情况。所以我觉得既然double占用的空间是无法避免的，那么驻留在老年代的heap空间短时间内不可能有明显的减少。为了解决之前应用发生MixedGC时Eden区异常收缩导致YGC异常的问题，必须固定一个下限。值，只能扩容，看能不能缓解容器内存大小。于是应用容器基线升级到4C16G，设置在16G容器环境，分配10G内存给堆空间，逐步升级线上服务的容器规格。结果用了两天。升级上线的大部分容器后，我查看监控，发现大型容器是没有FGC的，而且得益于大堆内存（10G），GC监控根本看不到。没有切包动作。但是，RPC成功率仍会下降（100%->97%），RPC线程池线程数仍会略有增加（50->~71）。由此可见，FGC并不是切包抖动的核心原因，背后还有更深层次的原因需要挖掘。高容器CPU触发自适应限流？再次询问受影响的业务方，通过下游应用的日志找到推包抖动的时间点，出现了很多sentinel限流日志。在结构化应用中，接口没有主动配置限流。只有组内的哨兵中间件可能会自动执行限流策略，因为它在某个时间点检测到CPU使用率过高（超过80%）。Sentinel是群内的流控中间件，可以以流量为切入点，帮助业务从限流、流量整形、断路器降级、系统自适应保护、热点保护等多个维度保障微服务的稳定性。登录发生限流的服务商对应的机器，确实看到了限流日志。$catcpu-sampling.log.1|grep"2022-05-1903:57"|grep-v"0.0"2022-05-1903:57:12.435|||applicationname|CpuSampling|0||4.151785714285714|1.0|6可以看到当前时刻CPU使用率达到了415%.可以看出，此时确实存在CPU的四个核心被充分利用的现象。但是从应用监控来看，此时机器的CPU使用率只有20%多（100%为单位）。而sentinel的cpu-sampling日志只grep出一个CPU满的日志。根据限流中间件，CPU频率每20ms采样一次，说明这只是CPU尖峰，应该不会有大范围的影响。笔者其实对限流导致的RPC成功率下降有点怀疑，我觉得应该不是这样的问题。不管怎样，最简单的验证方法就是在网上找一台已经换成16G内存的机器，将sentinel中间件设置为dryrun模式，只记录日志，不做实际的限流动作。看看接口成功率会不会下降。根据以上推理，CPU尖峰最长不会超过40ms，即使CPU占满40ms，也不会导致接口超时几秒。结果到了晚上，接口的成功率还是下降了，接口出现几秒的超时。偷看源码，探究类目客户端在切包过程中的具体动作，发现单纯增加容器规格并不能解决切包抖动的问题，笔者回顾了一下自己已经掌握的线索：1.FGC没有造成分包抖动的核心原因是花钱升级容器后得到的结论。那么，如果我们不花这笔钱，是否可以单纯从监测中得出结论呢？其实是可以的。如果目前线上的容器规格不能满足分包所需的内存消耗，理论上集群中的每台机器在分包时都会进行FGC。大概20次左右，而且只有1/6的机子有FGC，其余机子只有YGC略有上升，然后很快恢复到正常水位。而且即使增加YGC的量，YGC从70ms增加到200ms也只需要一分钟的时间，不足以造成大量接口超时。2、Sentinel检测CPU尖峰，自动限流，确实会降低服务成功率。但是，即使关闭限流，接口仍然有几秒的超时，说明限流并不是接口成功率下降的主要原因。3.categoryclient是把category数据存放在磁盘上，堆里，还是堆外内存里，问了一圈，各有各的看法。但是，不同的存储方式最终可能会得出完全不同的结论。为了弄清楚这个问题，最准确的方法是阅读类别客户端包的源代码。于是笔者花了点时间，查看了分类服务包的整个切包过程，是在分类客户端自带的nettyChannelHandler回调线程中单线程执行的，并没有多线程并行加载动作.在初始化类目服务入口时，虽然有很多看似重计算的动作，比如建立索引，但是由于底层是单线程执行的，理论上CPU最多可以打到100%（一核），会有没有命中。到400%的情况。凌晨的结构化应用CPU使用率很低，不到10%。理论上，切包+业务不会导致CPU被占满。更不可能导致服务无响应数秒。随着进一步梳理切包出错的时间点和日志信息，一个更奇怪的现象浮出水面。异常现象：切包后，接口开始超时。观察如下全链路日志：com.taobao.idle.modulet.ItemKgraphServiceApi@getSpuPublishSearchV3~SMMinterfacehastimeoutupto8s。请注意，此错误发生在2022-05-2401:38:19.523。通常，该接口的RT约为400m。底层是利用线程池并行调用各种搜索服务。整体设置了1s的超时时间，大量的trycatch包基本不会报错。查看这个时间点附近的类目树日志：可以看到在01:38:00，类目数据已经切换。01:38:14，连旧文件都被删除了。切袋结束。但是，在01:38:27，类别服务的记录器之一从kGraphCommonFixedThreadFactory-10-thread-95线程打印了两行日志：2022-05-2401:38:27.715[kGraphCommonFixedThreadFactory-10-thread-95][]WARN类别服务记录器-加载std_category_property_value存储的缓存已完成。耗时7820ms，缓存278块。2022-05-2401:38:31.236[kGraphCommonFixedThreadFactory-10-thread-95][]WARN类目标服务记录器-加载std_category_property_value存储的缓存已完成。耗时11341ms，缓存109块。而这个线程池就是运行getSpuPublishSearchV3接口底层传递各种搜索的执行线程，代码为异步执行的Future设置了1s的超时时间，如果执行超过1秒，接口服务的代码将不会继续等待，但会直接执行。更巧合的是：从01:38:19到01:38:27，整整8秒，刚好和上面监控的超时时间吻合。看到这里，问题似乎变得更加复杂了。1、刚才我们提到，切包是在类目客户端的nettyChannelHandler线程中进行的。为什么现在跑在业务线程池上了，还挂了接口？2、为什么所有类别服务都运行在其他线程池上，并且线程池超时设置为1s，为什么接口还是有8s的超时时间？拨开云层，一一看到迷雾，不难回答问题1。因为日志已经打出来了，所以只需要搜索全局加载缓存，找到分类树中唯一打日志的地方，然后上下查找调用栈即可。你会发现类目属性和类目属性值这两个存储是懒加载的。只有切包后，第一个请求读取类别的属性和属性值才会触发将store文件通过mmap映射到Java进程的一个连续虚拟地址的动作，并从中读取数据磁盘到内存。.核心代码：MappedByteBuffermappedBuffer=storeFile.getFileChannel().map(MapMode.READ_ONLY,segmentPosition,segmentSize);//创建mmap映射mappedBuffer.load();//将数据读入内存Bufferbuffer=FixedByteBuffer.wrap(mapppedBuffer);this.bufferCacheArray[t]=newBufferCache(buffer,((t==0)?meta.getHeaderSize():0),blockCountThisSegment,meta.getBlockSize());for(inti=((t==0)?0:blockIdFlags[t-1]);iblockbuffer的映射}所以加载后的日志自然是在业务的线程池中播放。PageFault的“power”问题2不好回答。因为有一个非常明显的矛盾：这次Store的加载是在业务线程池中加载的，所有的Futures只等待1s。如果1s没加载完，马上返回，不可能用8s。而且机器已经是16G的容器，并没有出现FGC导致的STW。那么只有进程级的挂起才会影响到多个线程。为了确认是否有进程hang，笔者再次查看了adaptivecpu-sampling日志。不知道没看到，看到就吓一跳：每20ms采样一次CPU并记录日志的线程也挂了！日志打印直到01:38:27才恢复。而这段时间恰好是store加载的时间，也恰逢接口超时时间。基本上只有一种可能，就是第一次读取mmap映射的虚拟地址段的数据时，因为数据在硬盘中，还没有存储。在内存上，会触发pagefault，导致JVM进程进入内核态，执行从磁盘加载数据到内存的pagefaulthandler，导致进程挂起，直到返回用户态.参考《Understanding the Linux kernel》中9.4.2地址空间内错误地址的处理。其中有一段是这样写的：如果handle_mm_fault()函数成功地为进程分配了一个新的页面框架，它会返回VM_FAULT_MINOR或VM_FAULT_MAJOR。值VM_FAULT_MINOR表示PageFault已经被处理，没有阻塞当前kind进程；PageFault称为minorfault。值VM_FAULT_MAJOR表示页面错误迫使当前进程进入睡眠状态（很可能是因为在用从磁盘读取的数据填充分配给进程的页面框架时花费了时间）；当前进程的页面错误称为主要错误。该函数还可以返回VM_FAULT_OOM（内存不足）或VM_FAULT_SIGBUS（所有其他错误）。注意粗体部分。在处理内存pagefault事件时，如果发生了MajorPagefault，那么这个Pagefault会强制当前进程休眠（基本发生在需要从磁盘读取数据到pageblock中的耗时场景）进程地址空间）。查看MappedByteBuffer#load()方法的Javadoc：您可以看到Javadoc指出：调用此方法可能会导致一些页面错误和I/O操作发生。调用此方法可能会产生一些页面错误。那么只要确认JVM进程在loadstore过程中产生了大量的MajorPageFaults，就可以解释为什么会出现跨多线程的Hang。这里笔者主要使用了两个命令：pmap和sar。pmap可以显示进程的所有连续地址空间。通过查看地址空间的文件引用和RSS列的值，可以表明当前连续内存空间中有多少页被进程引用。在普通机器上重现这一场景，可以看到在执行loadstore方法之前，当前进程并没有引用任何与类别文??件相关的虚拟地址空间。调用查询属性和属性值的方法后，可以看到类别树的属性和属性值存储都加载了，RSS值==KBytes，说明整个文件已经读入内存。另一个重要的手是sar命令。sar命令可以按照指定的采样率对当前整个操作系统的PageFault发生指标进行采样。可以看出，在initCache过程中，触发了大量的重大页面错误，笔者连接服务器的Arthas命令行也挂了，没有任何反应。上述情况得到进一步验证。Arthas命令行底层是termd库，是纯Java实现的。而Arthas以java代理的形式依附于目标JVM。如果Arthas的控制台输入命令没有回显，基本上只有一种可能是JVM进程整体挂掉。这一现象进一步验证了上述。提到的进程卡在了内核状态挂起的假设中。那为什么要挂几秒？通过测量线上容器的IO速度，发现容器的磁盘读写速度在100MB左右，category属性值的store文件很大，达到了1.7G。一次加载此文件非常耗时。至此，我们终于可以得出结论了。结语结构化应用每夜分类客户端推送包完成新旧数据包版本切换后，存储分类属性和属性值的数据不会立即加载到内存中。它会等到第一个查询类别属性和属性值的请求到来后才懒加载数据到内存中。因为类别属性值存储非常大，达到1.7G。在将1.7G数据整体加载到内存的过程中触发了大量的MajorPageFaults，导致进程进入内核态处理pagefault异常。但是由于业务容器的IO性能不佳，完整读取文件非常耗时，最终导致Java进程挂起十几秒。最终的解决办法是有问题请教类目服务相关的同学，他们的建议是升级到最新版本的客户端。笔者对比了新老版本客户端的代码，主要有两点改进。1.在切包之前，会先加载一个store，而不是等request进来再懒加载。2、store加载的时候，不是一次性加载整个文件，而是把文件分成64M的小块，每次加载64M，然后休眠一会。继续加载下一个块，避免一次加载一个大文件块，导致进程长期停留在内核态，无法对外提供服务。退后一步，考虑一下之前提出的一些问题。由于接口超时主要是加载大文件导致的，是否需要升级16G容器？笔者认为还是有必要的。有两个原因。1、现在新版类目客户端在切换版本释放旧包资源（包括虚拟地址空间）前会加载一个store。store虽然在堆外内存，但还是需要占用进程的地址空间，实际上还需要将数据读入内存。所以在切包过程中，从整个Java进程来看，确实会占用doublestore空间。目前一个类目店是1.7G，两个是3.4G。还有4G空间分配给JVM堆。剩下不到1G的内存空间，8G的容器内存非常紧张。切包过程中加载新store时容易产生容器OOM，导致容器被kill掉。2.虽然store数据存在于堆外，但是store的一些索引对象和元数据仍然存在于堆中，占用堆空间6-700M左右。不管是新版还是老版的类目客户端，都是先建索引再切包。所以在新建包索引时，峰值也会产生两倍的堆空间占用，很容易因为堆内存不足导致YGC甚至FGC。总结一个看起来和GC很像的接口超时，但是底层隐藏了更深层次的原因。通过这个案例，也提醒我们，作为一个技术人员，在遇到问题的时候，无论表象多么明显，或者与我们之前遇到的场景多么相似，都要避免被这样蒙蔽双眼的坏习惯——称为经验和先入为主。大胆推理，慎重论证。只有多问为什么，才能一步步接近真相。