分布式令人头疼的堆外内存泄露怎么排查？

　　作者：鲍凤其
　　爱可生dble团队开发成员，主要负责dble需求开发，故障排查和社区问题解答。少说废话，放码过来。
　　本文来源：原创投稿
　　爱可生开源社区出品，原创内容未经授权不得随意使用，转载请联系小编并注明来源。
　　大家在使用JavaNIO的过程中，是不是也遇到过堆外内存泄露的问题？是不是也苦恼过如何排查？
　　下面就给大家介绍一个在dble中排查堆外内存泄露的案例。现象
　　有客户在使用dble之后，有一天dble对后端MySQL实例的心跳检测全部超时，导致业务中断，最后通过重启解决。分析过程dble日志
　　首先当然是分析dble日志。从dble日志中可以发现：故障时间点所有后端MySQL实例心跳都超时日志中出现大量Youmayneedtoturnuppagesize。ThemaximumsizeoftheDirectByteBufferPoolthatcanbeallocatedatonetimeis2097152，andthesizethatyouwouldliketoallocateis4194304的日志
　　日志片段：心跳超时2022081511：40：32。147WARN〔TimerScheduler0〕（com。actiontech。dble。backend。heartbeat。MySQLHeartbeat。setTimeout（MySQLHeartbeat。java：251））heartbeatto〔xxxx：3306〕setTimeout，previousstatusis1堆外内存可能泄露的可疑ahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a2022081511：40：32。153WARN〔NIOREACTORBACKEND20RW〕（com。actiontech。dble。buffer。DirectByteBufferPool。allocate（DirectByteBufferPool。java：76））Youmayneedtoturnuppagesize。ThemaximumsizeoftheDirectByteBufferPoolthatcanbeallocatedatonetimeis2097152，andthesizethatyouwouldliketoallocateis4194304
　　通过上面的日志猜测：所有MySQL实例超时是很特殊的，可能是由于故障时间发生了长时间停顿的gc而长时间停顿的gc可能是由于堆外内存不够，大量的业务流量涌进堆内存中，从而导致频繁的gc验证猜想
　　为了验证上面的猜想，获取了dble机器的相关监控来看。
　　故障时dble机器的内存图：
　　可以看到确实存在短时间攀升。而dblecpu当时的使用率也很高。
　　再来看dble中freebuffer的监控图（这个指标是记录dble中Processor的堆外内存使用情况的）：
　　从图中可以看到，从dble启动后堆外内存呈现递减的趋势。
　　通过上面的监控图，基本可以确认故障发生时的时序关系：
　　堆外内存长期呈现递减的趋势，堆外内存耗尽之后，在dble中会使用堆内存存储网络报文。
　　当业务流量比较大时，堆内存被迅速消耗，从而导致频繁的fullgc。这样dble来不及处理MySQL实例心跳的返回报文，就引发了生产上的一些列问题。堆外内存泄露分析
　　从上面的分析来看，根因是堆外内存泄露，因此需要排查dble中堆外内存泄露的点。
　　考虑到dble中分配和释放堆外内存的操作比较集中，采用了btrace对分配和释放的方法进行了采集。btrace脚本
　　该脚本主要记录分配和释放的对外内存的内存地址。
　　运行此脚本后，对程序的性能有1020的损耗，且日志量较大，由于堆外内存呈长期递减的趋势，因此只采集了2h的日志进行分析：packagecom。actiontech。dble。btrace。script；importcom。sun。btrace。BTraceUtils；importcom。sun。btrace。annotations。；importsun。nio。ch。DirectBuffer；importjava。nio。ByteBuffer；BTrace（unsafetrue）publicclassBTraceDirectByteBuffer｛privateBTraceDirectByteBuffer（）｛｝OnMethod（clazzcom。actiontech。dble。buffer。DirectByteBufferPool，methodrecycle，locationLocation（Kind。RETURN））publicstaticvoidrecycle（ProbeClassNameStringpcn，ProbeMethodNameStringpmn，ByteBufferbuf）｛StringthreadNameBTraceUtils。currentThread（）。getName（）；排除一些线程的干扰if（！threadName。contains（writeTo））｛StringjsBTraceUtils。jstackStr（15）；if（！js。contains（heartbeat）！js。contains（XAAnalysisHandler））｛BTraceUtils。println（threadName）；if（buf。isDirect（））｛BTraceUtils。println（r：（（DirectBuffer）buf）。address（））；｝BTraceUtils。println（js）；｝｝｝OnMethod（clazzcom。actiontech。dble。buffer。DirectByteBufferPool，methodallocate，locationLocation（Kind。RETURN））publicstaticvoidallocate（ReturnByteBufferbuf）｛StringthreadNameBTraceUtils。currentThread（）。getName（）；排除一些线程的干扰if（！threadName。contains（writeTo））｛StringjsBTraceUtils。jstackStr（15）；排除心跳等功能的干扰if（！js。contains（heartbeat）！js。contains（XAAnalysisHandler））｛BTraceUtils。println（threadName）；if（buf。isDirect（））｛BTraceUtils。println（a：（（DirectBuffer）buf）。address（））；｝BTraceUtils。println（js）；｝｝｝｝分析采集的btrace日志
　　采集命令：btraceoahrefhttps：www。bs178。comrizhitargetblankclassinfotextkey日志a的路径u11735pathtoBTraceDirectByteBuffer。java
　　过滤出分配的堆外内存的地址：grepa：tmp14220dblebtrace。logallocat。txtseds。。allocat。txtallocataddr。txt删除前两个字符
　　过滤出释放的堆外内存的地址：grepr：tmp14220dblebtrace。logrelease。txtseds。。release。txtreleaseaddr。txt删除前两个字符
　　此时取两个文件的差集：sortallocataddr。txtreleaseaddr。txtuniqures。txt
　　这样res。txt得到的是仅仅分配而没有释放的堆外内存（可能会有不准确）
　　从中任选几个堆外内存的address，查看堆栈。排除掉误记录的堆栈后，出现最多的堆栈如下：complexQueryExecutor176019a：139999811142058com。actiontech。dble。buffer。DirectByteBufferPool。allocate（DirectByteBufferPool。java：82）com。actiontech。dble。net。connection。AbstractConnection。allocate（AbstractConnection。java：395）com。actiontech。dble。backend。mysql。nio。handler。query。impl。OutputHandler。init（OutputHandler。java：51）com。actiontech。dble。services。factorys。FinalHandlerFactory。createFinalHandler（FinalHandlerFactory。java：28）com。actiontech。dble。backend。mysql。nio。handler。builder。HandlerBuilder。build（HandlerBuilder。java：90）com。actiontech。dble。server。NonBlockingSession。executeMultiResultSet（NonBlockingSession。java：608）com。actiontech。dble。server。NonBlockingSession。lambdaexecuteMultiSelect55（NonBlockingSession。java：670）java。util。concurrent。ThreadPoolExecutor。runWorker（ThreadPoolExecutor。java：1149）java。util。concurrent。ThreadPoolExecutorWorker。run（ThreadPoolExecutor。java：624）java。lang。Thread。run（Thread。java：748）review代码
　　在通过btrace知道了dble中的泄露点之后，下面就回到dble的代码中review代码。
　　首先通过上面的堆栈定位到下面的代码：comactiontechdblebackendmysqlniohandlerbuilderHandlerBuilder。javapublicRouteResultsetNodebuild（booleanisHaveHintPlan2Inner）throwsException｛TraceManager。TraceObjecttraceObjectTraceManager。serviceTrace（session。getShardingService（），buildexecutecomplexsql）；try｛finallongstartTimeSystem。nanoTime（）；BaseHandlerBuilderbuildergetBuilder（session，node，false）；DMLResponseHandlerendHandlerbuilder。getEndHandler（）；泄露点在这，dble会创建OutputHandler实例，OutputHandler会分配堆外内存DMLResponseHandlerfhFinalHandlerFactory。createFinalHandler（session）；endHandler。setNextHandler（fh）；。。。RouteResultsetNoderouteSingleNodegetTryRouteSingleNode（builder，isHaveHintPlan2Inner）；if（routeSingleNode！null）returnrouteSingleNode；HandlerBuilder。startHandler（fh）；session。endComplexExecute（）；longendTimeSystem。nanoTime（）；LOGGER。debug（HandlerBuilder。buildcost：（endTimestartTime））；session。setTraceBuilder（builder）；｝finally｛TraceManager。finishSpan（session。getShardingService（），traceObject）；｝returnnull；｝comactiontechdblebackendmysqlniohandlerqueryimplOutputHandler。javapublicOutputHandler（longid，NonBlockingSessionsession）｛super（id，session）；session。setOutputHandler（this）；this。locknewReentrantLock（）；this。packetId（byte）session。getPacketId（）。get（）；this。isBinarysession。isPrepared（）；分配堆外内存this。buffersession。getSource（）。allocate（）；｝
　　通过上面的代码可以判断在构造复杂查询执行链的时候会分配堆外内存。
　　问题到这其实还是没有解决，上述代码仅仅找到了堆外内存分配的地方，堆外内存没有释放仍然有以下几种可能：程序bug导致复杂查询未下发，从而执行链被丢弃而没有回收buffer程序下发了，由于未知bug导致没有释放buffer
　　dble中复杂查询的下发和执行都是异步调用并且逻辑链比较复杂，因此很难通过review代码的方式确认是哪种情况导致。
　　那如何进一步缩小范围呢？堆内存dump
　　既然堆外内存泄露的比较快，平常状态下的dump文件中应该可以找到异常的没有被回收的OutputHandler实例。
　　在dble复杂查询的执行链中，OutputHandler实例的生命周期往往伴随着BaseSelectHandler，因此是否可以通过异常OutputHandler的BaseSelectHandler来确定复杂查询有没有下发来进一步缩小范围。
　　通过现场收集到的异常OutputHandler中buffer的状态是：
　　正常写出的OutputHandler中buffer的状态是：
　　找到的异常的OutputHandler的BaseSelectHandler中状态值：
　　可以看出其中的状态值都是初始值，可以认为，异常的OutputHandler执行链没有被执行就被丢弃了。
　　这样范围被进一步缩小，此次堆外内存泄露是由于程序bug导致复杂查询的执行链被丢弃而导致的。
　　重新回到代码中，review下发复杂查询之前和构造之后的代码：comactiontechdblebackendmysqlniohandlerbuilderHandlerBuilder。javapublicRouteResultsetNodebuild（booleanisHaveHintPlan2Inner）throwsException｛TraceManager。TraceObjecttraceObjectTraceManager。serviceTrace（session。getShardingService（），buildexecutecomplexsql）；try｛finallongstartTimeSystem。nanoTime（）；BaseHandlerBuilderbuildergetBuilder（session，node，false）；DMLResponseHandlerendHandlerbuilder。getEndHandler（）；泄露点在这，dble会创建OutputHandler，OutputHandler会分配堆外内存DMLResponseHandlerfhFinalHandlerFactory。createFinalHandler（session）；endHandler。setNextHandler（fh）；。。。RouteResultsetNoderouteSingleNodegetTryRouteSingleNode（builder，isHaveHintPlan2Inner）；if（routeSingleNode！null）returnrouteSingleNode；下发复杂查询，review之前的代码HandlerBuilder。startHandler（fh）；session。endComplexExecute（）；longendTimeSystem。nanoTime（）；LOGGER。debug（HandlerBuilder。buildcost：（endTimestartTime））；session。setTraceBuilder（builder）；｝finally｛TraceManager。finishSpan（session。getShardingService（），traceObject）；｝returnnull；｝
　　review到startHandler的时候，上一个语句returnrouteSingleNode引起了我的注意。
　　按照逻辑，岂不是如果符合条件routeSingleNode！null，就不会执行startHandler，而直接返回了。而且执行链的作用域在本方法内，不存在方法外的回收操作，这不就满足了未下发而直接返回的条件了。
　　至此，泄露的原因找到了。修复
　　修复的话，在OutputHandler中，不采取预分配buffer，而是使用到的时候才会进行分配。总结
　　到这里，整个堆外内存泄露的排查就结束了。希望对大家有帮助。