大约在上个月,利用WinDbg找到了软件中的一个存在很久的内存会暴涨的bug,说起来也是巧合,这里记录一下。
在描述问题之前,我想提一下,软件开发中寻找bug的正确思路和方法,这也是从我leader那里学到的严谨态度,并且在工作中体会最深的。
归零评审
前几天看到一个新闻,说的是国产蓝箭航天的朱雀二号遥一运载火箭飞行故障通过归零评审。
2023年3月18日,蓝箭航天空间科技股份有限公司组织召开朱雀二号遥一运载火箭二级游机异常关机故障归零评审会议。评审专家组经评议,一致认为朱雀二号遥一运载火箭二级游机异常关机故障问题定位准确、机理清楚,在发动机地面试车中故障复现,采取的改进措施经验证有效,可以归零。朱雀二号遥一运载火箭于2022年12月14日16:30在中国酒泉卫星发射中心点火起飞,一级飞行、一二级分离、二级点火、整流罩分离均正常,二级主机关机后游机异常关机,发射任务失利。任务失利后,蓝箭航天成立归零工作组组织开展故障分析工作,定位故障原因、分析故障模式和故障机理。通过对飞行遥测数据的详细分析,策划开展了全面的仿真分析计算和一系列试验验证及热试车工作,查明了故障原因和故障机理。二级游机异常关机故障定位于游机氧输送管与氧泵低压壳体连接部位刚度不匹配,低压壳体存在强度裕度不足,在主机关机水击作用下氧泵低压壳体破裂,引发游机异常关机故障。针对故障原因和机理,蓝箭航天采取了多项改进措施提高结构安全系数、减小水击影响,改进措施经过仿真分析计算和地面试车考核验证有效,能够满足飞行要求。感谢评审专家组在归零过程中对蓝箭航天的指导与帮助,感谢客户的信任和理解,感谢所有股东单位的长期陪伴和支持。后续,公司将全面启动朱雀二号遥二运载火箭的总装总测工作,迅速落实故障改进措施,不断增强团队质量意识、忧患意识、责任意识,心怀敬畏,严密组织朱雀二号的复飞工作,确保后续发射任务持续圆满成功。
看到这个我不禁感概,其实软件开发中bug的修复往大的严谨的方面来说,流程跟这个火箭发射失败“归零评审”的思路是一样的。虽然在日常中软件的一个bug可能不会总是像火箭发射损失那么大,但历史上真的有因为软件的bug导致火箭发射失败的例子,最有名的应该算是欧空局的阿丽亚娜(Ariane)5型火箭爆炸了(详见 一行代码引发的“血案”:价值5亿欧元的火箭,发射40秒后凌空爆炸 ,这个例子实在是太有名以至于都被钉到类型转换溢出的耻辱柱上了,CSAPP这本书都把它写了进去🤣)。
正确的思路和方法
借着上面这个火箭发射失败的归零评审,我想说的是在日常中解决程序bug的思路,简单来说就是:
- What (happend)
- Why (it happend)
- How (to fixed)
以我20年的工程经验,大部份人太性急、太过早跳到第3步how,而把第1-2混为一谈导致陷入了无限循环,因此无法把第2步完成,最终也到达不了第3步。把1与2理清楚,是最难的部分,第3却往往最容易。-------《来源网上,出处不明😊》
就像上面说的,其实第2步最难,但第1步在有些时候也很难。
先说第1步 What happend ? 发生了什么?这个其实就是问题重现。我们确实观察到了异常,但这个异常在开发或测试环境要重现出来有时却不容易,这就是常常碰到的 “在我电脑上好好的呀,怎么到你电脑上就出问题了?" 。生产环境的bug有时候很难重现,出了问题,老板或许就站在你旁边要求第一时间最快搞定问题(实际的问题或原因可以后面解决但首要要先把系统恢复正常)。
- 这种急迫的、万分火急的情况导致有时无法保留现场,比如如果程序异常是由内存暴涨或者CPU占满导致,要把进程的内容dump出来可能要花很长时间,因为这时候计算机的内存或者CPU已经耗尽,要执行额外的任务,写入一个很大的dump文件将会是一个漫长的过程,生产环境无法容忍,所以最快最简单的就是重启进程或重启计算机,但重启之后这些宝贵的“犯罪现场”的数据也就没有了。有一个解决办法是使用ProcDump这种自动化的dump方式,在程序内存占用上升到某个设定的值时自动dump。
- 另外生产环境的数据在开发过程中其实很难模拟,比如说证券市场中的行情,数据流量在没有事先测量和了解之前,很难在模拟环境做一份跟实际的生产环境一模一样的,尤其是不同时间的数据流量很难准确模拟,比如在股市开盘阶段,交易活跃数据流量就很大,盘中行情冷淡时期,数据量就会很小。
- 还有一种情况是,生产环境的数据,开发人员是无法获取到的,比如我之前参与的某旅行App里“高端美食”的模块开发,生产环境因为涉及到商业机密或用户数据这些敏感信息,程序员是获取不到的。这个时候就只能全靠模拟数据或者压力测试。
- 最后一个问题就是生产环境的硬件可能跟开发或测试环境不一样,有时候可能也不全是软件的问题,可能跟硬件或者操作系统也有关。解决这种不一致的问题的一个办法就是使用容器技术比如docker。
在开发过程中,能做的就是尽量把各种脚手架都搭建好,尽量能仿真生产环境,如果不能做到对生产环境的重建,那么做一个比生产环境更加恶劣的仿真环境也可以,这其实就是压力测试。还是拿证券行情的例子来说,如果有个程序要处理行情数据,那么我们可以选取交易量大的某一天的落地数据(得写个程序落地行情数据)进行测试,流量的话,可以用超过正常流量的倍数来进行回放。如果这种环境能顶得住,那么比这个弱的生产环境应该问题不大。
第2步的 Why it happend?其实也很难,尤其是在第1步没有找到规律的可复现的场景时。有一个重要的80-20法则,一个程序的80%的资源用于20%的代码上,80%的执行时间花在大约20%的代码身上,80%的内存被大约20%的代码使用,80%的磁盘访问动作由20%的动作执行,80%的维护力气花在20%的代码上面,80%的代码的执行效率不会影响系统整体性能。如果程序性能有问题,那么瓶颈大概就在那20%里。
大部分人采用的瓶颈查找方法是靠“猜”。用经验猜,用直觉猜,用意大利纸牌猜,或是请碟仙,或是根据谣言,或更糟糕的是根据历代相传流于仪式的宣称:因为网络的延迟啦,因为内存分配器没有做适当的调整啦,因为编译器没有足够的优化啦......
大部分程序员对程序的性能特质,都有错误的直觉,因为程序的性能特质倾向高度的非直觉性。结果,无数的努力灌注在一些绝对无法提升整体性能的程序段落头上,形成严重的精力浪费。举个例子,我们当然可以采用某些特选的算法和数据结构加入程序中,来减少运算量,但如果这个程序受制于I/O(所谓I/O-bound),那么前面的种种努力对性能就一点帮助也没有。我们可以选用威力强化的I/O程序库来取代编译器所附的版本,但如果程序受制于CPU(所谓CPU-bound),这对性能也发挥不了什么作用。
那么,如果你面对一个迟缓的程序或是一个内存用量过大的程序,你该怎么办?80-20法则告诉我们,如果你只是东一块西一块地改善程序,病急乱投医,头痛医头,脚痛医脚,不会有太大帮助。“程序的性能图特质倾向于高度的非直觉性”这个事实意味着,企图猜出性能瓶颈之所在,比头痛医头,脚痛医脚更是不如,那么什么是可行之道?
可行之道就是完全根据观察或实验来识别造成你心痛的那20%代码。而辨识之道就是借助某个程序分析器(program profiler)。然而不是任何分析器都足以堪大任,他必须可以直接测量你所在意的资源。例如,假如你的程序太慢,你需要一个分析器告诉你程序的不同区段各花费多少时间,于是你便可以专注在特别耗时的地方加以改善,这不但可以巨幅提升局部效率,对整体效率也有极大帮助。
-------《More Effective C++:35 New Ways to Improve Your Programs and Designs》
如果观察到了第1步的现象,但不能复现时(能复现可能就已经找到原因了),不能靠猜。在动手改进前,一定要想好测试或测量方案,来比较优化前后,性能是否改进,问题是否已经得到修正。这里有很多性能测试器能够派上用场,比如Windows自带的性能计数器、CLR Profile、PerfView、WinDbg等。如果是编写.NET程序,PefView这个工具尤其重要,它是由微软工程师编写,并且.NET运行时团队也用它来分析程序性能。总之性能指标一定要量化,不能靠猜和“我觉得”,因为如前所述,程序的性能特质倾向于高度的非直觉性。
即使用工具测量,仍然可能只是找到了那80%的不重要的性能问题。剩下的就是尽可能的仿真真实环境,做压力测试和尽量争取重现问题,在开发或者测试环境重现问题后,就可以获取到dump,从而利用WinDbg等工具做进一步的逆向分析了,后面我会举例说明这个问题。当然还可以配合使用夹逼调试法缩小问题范围。
第3步How to fix ,如何修补相对来说是最简单最容易不过的了。
下面我以最近解决的一个长久以来内存暴涨的例子来说明以上的思路和解决方法。
问题的出现
我们有一个行情订阅转发程序,名为DataFeedGateway,可以认为是一个C/S系统。这个程序会接从行情供应商那里接来所有证券市场的行情数据,客户端Client向DataFeedGateway发起订阅请求,DataFeedGateway程序根据客户的订阅给客户发送相应证券代码的行情数据。客户端跟DataFeedGateway程序通过TCP通信,基本的格式为,消息大小+消息主体。
▲ DataFeedGateway接收Client的行情订阅信息,然后将收到的对应行情转发到对应的客户端上
这个程序运行了很多年,但极少时候会出现内存暴涨的情况,比如下面这个图,这是2022年5月12日这一天,当时上海处于封城期间,大家都在家里远程办公,当时客户反应行情很慢,远程到机房服务器上后发现这个程序消耗了服务器所有8G内存中的6GB,但CPU的占用并不高。为了尽快解决问题,就重启了,重启后正常。
▲太残暴了,直接快把内存占满了
当时分析了日志,怀疑是某个客户端接收数据产生了阻塞,导致数据都堆积在转发程序的待发送队列里,发送不出去,于是减少了待转发数据队列的长度。超过这个长度还没发送出去的数据直接丢弃(其实这里仍然有个疑问,多么大量的数据能够产生这么多的堆积?但由于没有保留好现场,只有从代码和有限的日志去猜和分析)。
▲ 不会是内存泄漏了吧,但似乎内存不是缓慢增加,而是突然在某种情况下一下子增大的
上个月的某一天,这个问题似乎又出现了,当天行情流量很大,客户反应行情很慢,重启后正常。在zabbix上观察服务器上的内存,也是在慢慢增长,当达到3-4G后客户就会反应行情接收很慢,只有再次重启,当天出现了好几次这种情况,每次只有重启才能解决,这一天是有史以来最严重的情况。
但接下来的几天却没有再现。
解决方法
最开始单纯觉得应该是流量大,于是搭建了行情模拟发送的平台,由于之前已经通过其它工具落地了那一天的数据,只需要将这些数据读取出来,然后往这个DataFeedGateway上发送就可以,同时,新建了很多个测试客户端,每个客户端都订阅了很多股票。程序运行后,使用CLR Profile等工具检测,发现确实有一些地方可以优化。比如改变算法,减少字符串的拼接,内存有一定的减少。
同时发现程序的另外一个可能导致内存增加的地方,由于客户端大概只有20多个,每个客户可能会订阅20-30只股票,所以在处理所有客户端的订阅时,使用了Parallel.ForEach的方式进行并行循环处理,希望同时处理多个客户端的订阅请求。但是当订阅的用户比较少时,Parallel.ForEach准备上下文或者上下文切换的时间可能要比直接采用普通的foreach遍历的方式还要长,内存占用还要大,这个是一个比较重要的优化地方,这个跟之前某个优化类似。当时是每个消息都新建一个Task来处理,这种做法相对于专门创建一个线程,然后把消息放到队列里,线程从队列里依次取出数据来处理效率有时更低。将Parallel.ForEach替换为普通的foreach之后,发现内存确实大幅减少,并且CPU的波动变小。在模拟仿真环境下,相比优化前确实内存不容易过高,且CPU波动减少,这两个case说明,在作并行化优化时,一定要根据数据量的大小进行详细的测试论证,对于数据量小的情况,或者需要处理的任务比较少的情况下,并行化可能并不能提高性能,反而会影响性能。于是把这一版本发布到生产环境。
优化还在继续,紧接着从流程分析,使用PefView等工具,发现转发程序在接收数据时需要进行解压缩,解压缩会创建大量的临时byte数组,这些数组对GC造成了很大压力,同时如果数据很大时,解压后的byte[]数组大小可能超过85K,导致大对象堆大小激增,从而使得内存占用过大,于是使用ArrayPool进行了优化。优化完成之后,发现内存有进一步大幅减少,而且内存的波动也有减少,CPU的占用率也减少,用户订阅股票后收到行情的延迟也有减少。
同时,在程序的GC的设置上也把GC设置为了服务器模式,这样能减少垃圾回收的延迟,同时也把服务器的内存和系统进行了升级,内存从8G升级为了16G,操作系统也从Windows 7 更换为了较新的Windows Server 2019。
这个优化完成之后,就把程序发布到生产环境了。同时测试环境也发布了一份。
但上线的当天,虽然没有出现之前的内存暴涨情况,但客户仍然反馈偶尔行情会慢,于是当天收盘之后,又退回到了Parallel.Foreach优化的这个版本,把使用ArrayPool这一版本放到了测试环境上,当时怀疑ArrayPool在创建缓存对象时可能会导致内存变大,这部分的优化可以单独写一篇文章来详细讨论,包括ArrayPool的源码的分析。
生产环境退回到上一个版本之后,测试环境对ArrayPool的优化继续进行,在研究了源码之后,设置了初始的大小和缓存数量,并把这一版本发布到了测试环境观察。
在线上运行的同时,在测试环境也在接收实盘的行情数据模拟,并且开了很多个订阅客户端,包括模拟慢速消费的订阅客户端。很长时间内存占用在200~300M左右,CPU最高也在10%左右,最低大概3%~5%,看起来非常正常,问题似乎解决了。在正常运行了大概几个星期之后,发现再也没有出现这个问题,于是就有把使用ArrayPool的这一版优化更新到了生产环境,现在生产环境和测试环境都是最新的版本。
似乎没那么简单
上述的优化大概在生产环境和测试环境运行了大概好几周,没有出现异常,至少在交易时间段没有出现异常。但内存问题我一直都在留意,直到有一天周一的早上,我在生产环境发现这个转发程序的内存占用又达到了大概2~3G,这种情况在测试环境和生产环境之前也遇到过(之前在测试环境遇到过是因为发送的大流量数据都花在解析数据上,很多数据解析后来不及转发堆积导致,生产环境不会有这么多数据,跟这个问题无关,所以没有在意),这有点不正常,并且这个程序在上周五收盘时,内存占用还挺正常的大概就200~300M,怎么突然运行了一个周末,就达到了2~3G,并且周末也没有客户端连接使用呀,也没有行情处理和转发,难道是存在内存泄漏,但之前的大部分周末却是好好的?程序在经过周末运行后内存有可能会变大,之前有几次也碰到过。每次遇到这个问题似乎都跟周末有关,遇到内存占用过大,在没开盘之前我都会把该进程的所有内容dump出来,记录好观察到的现象,保护好现场,供以后分析使用。
要分析dump最方便的是使用WinDbg,不得不承认,在此之前尝试学习过WinDbg,但当时的环境搭建很麻烦,就放弃了。这次遇到问题我大概花了一个多星期的下班在家时间,初略的了解的WinDbg的一些命令和针对.NET的调试方法,当然网上有一些资源,比如《.NET 高级调试》经典书籍视频解读系列课强烈推荐。
在学习WinDbg的过程中,我也尝试分析之前Dump下来的文件,在某一天早晨分析出来一点问题之后继而跟leader讨论,深藏已久的问题逐渐浮出水面。
问题再现
最有效的方法就是打开Dump文件开始分析,这里我选择的是在生产环境,经过一个周末运行后内存达到了2-3G的这个异常情况下的Dump文件。
既然是内存过高,第一步就是看看托管堆的情况,首先查看GC的模式,可以通过!eeversion来查看GC模式:
0:000> !eeversion
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
4.7.3324.0 free
Server mode with 12 gc heaps
SOS Version: 4.8.4614.0 retail build
可以看到,这里程序配置的GC模式是服务器模式(Server),总共有12个GC堆,这也跟CPU的逻辑处理器个数一致。如果设置为工作站模式(workstation)就只会有一个GC堆。
▲具有12个逻辑处理器的服务器
接下来使用!eeheap -gc来查看托管堆信息,这里主要是查看各个堆的大小,以及起始地址,以方便进一步分析。
0:000> !eeheap -gc
Number of GC Heaps: 12
------------------------------
Heap 0 (0000022a54cebf90)
generation 0 starts at 0x0000022a555ab848
generation 1 starts at 0x0000022a555ab690
generation 2 starts at 0x0000022a55591000
ephemeral segment allocation context: none
segment begin allocated size
0000022a55590000 0000022a55591000 0000022a55607860 0x76860(485472)
Large object heap starts at 0x0000022d55591000
segment begin allocated size
0000022d55590000 0000022d55591000 0000022d555b3180 0x22180(139648)
0000022a00000000 0000022a00001000 0000022a2f001040 0x2f000040(788529216)
Heap Size: Size: 0x2f098a20 (789154336) bytes.
------------------------------
Heap 1 (0000022a54d14d20)
generation 0 starts at 0x0000022a955c7d30
generation 1 starts at 0x0000022a955c7930
generation 2 starts at 0x0000022a95591000
ephemeral segment allocation context: none
segment begin allocated size
0000022a95590000 0000022a95591000 0000022a95cc8350 0x737350(7566160)
Large object heap starts at 0x0000022d65591000
segment begin allocated size
0000022d65590000 0000022d65591000 0000022d65591018 0x18(24)
Heap Size: Size: 0x737368 (7566184) bytes.
------------------------------
Heap 2 (0000022a54d3f390)
generation 0 starts at 0x0000022ad55bc6b0
generation 1 starts at 0x0000022ad55bbf50
generation 2 starts at 0x0000022ad5591000
ephemeral segment allocation context: none
segment begin allocated size
0000022ad5590000 0000022ad5591000 0000022ad56386c8 0xa76c8(685768)
Large object heap starts at 0x0000022d75591000
segment begin allocated size
0000022d75590000 0000022d75591000 0000022d755b1050 0x20050(131152)
Heap Size: Size: 0xc7718 (816920) bytes.
------------------------------
Heap 3 (0000022a55477530)
generation 0 starts at 0x0000022b1559f3d8
generation 1 starts at 0x0000022b1559eaf0
generation 2 starts at 0x0000022b15591000
ephemeral segment allocation context: none
segment begin allocated size
0000022b15590000 0000022b15591000 0000022b15741618 0x1b0618(1771032)
Large object heap starts at 0x0000022d85591000
segment begin allocated size
0000022d85590000 0000022d85591000 0000022d85591018 0x18(24)
Heap Size: Size: 0x1b0630 (1771056) bytes.
------------------------------
Heap 4 (0000022a5547a740)
generation 0 starts at 0x0000022b55671520
generation 1 starts at 0x0000022b55670e90
generation 2 starts at 0x0000022b55591000
ephemeral segment allocation context: none
segment begin allocated size
0000022b55590000 0000022b55591000 0000022b55755538 0x1c4538(1852728)
Large object heap starts at 0x0000022d95591000
segment begin allocated size
0000022d95590000 0000022d95591000 0000022d95631130 0xa0130(655664)
Heap Size: Size: 0x264668 (2508392) bytes.
------------------------------
Heap 5 (0000022a55467ae0)
generation 0 starts at 0x0000022b955a0b98
generation 1 starts at 0x0000022b955a0918
generation 2 starts at 0x0000022b95591000
ephemeral segment allocation context: none
segment begin allocated size
0000022b95590000 0000022b95591000 0000022b955c2bb0 0x31bb0(203696)
Large object heap starts at 0x0000022da5591000
segment begin allocated size
0000022da5590000 0000022da5591000 0000022da55b1050 0x20050(131152)
Heap Size: Size: 0x51c00 (334848) bytes.
------------------------------
Heap 6 (0000022a5546acf0)
generation 0 starts at 0x0000022bd564d370
generation 1 starts at 0x0000022bd564b720
generation 2 starts at 0x0000022bd5591000
ephemeral segment allocation context: none
segment begin allocated size
0000022bd5590000 0000022bd5591000 0000022bd5e09120 0x878120(8880416)
Large object heap starts at 0x0000022db5591000
segment begin allocated size
0000022db5590000 0000022db5591000 0000022db55b1050 0x20050(131152)
Heap Size: Size: 0x898170 (9011568) bytes.
------------------------------
Heap 7 (0000022a55474320)
generation 0 starts at 0x0000022c155c5978
generation 1 starts at 0x0000022c155c57e0
generation 2 starts at 0x0000022c15591000
ephemeral segment allocation context: none
segment begin allocated size
0000022c15590000 0000022c15591000 0000022c1561f990 0x8e990(584080)
Large object heap starts at 0x0000022dc5591000
segment begin allocated size
0000022dc5590000 0000022dc5591000 0000022dc5591018 0x18(24)
Heap Size: Size: 0x8e9a8 (584104) bytes.
------------------------------
Heap 8 (0000022a554648d0)
generation 0 starts at 0x0000022c555d3348
generation 1 starts at 0x0000022c555c6300
generation 2 starts at 0x0000022c55591000
ephemeral segment allocation context: none
segment begin allocated size
0000022c55590000 0000022c55591000 0000022c555f7360 0x66360(418656)
Large object heap starts at 0x0000022dd5591000
segment begin allocated size
0000022dd5590000 0000022dd5591000 0000022dd5591018 0x18(24)
0000022e215d0000 0000022e215d1000 0000022e505d1040 0x2f000040(788529216)
Heap Size: Size: 0x2f0663b8 (788947896) bytes.
------------------------------
Heap 9 (0000022a5547d950)
generation 0 starts at 0x0000022c955cdb78
generation 1 starts at 0x0000022c955cd9e0
generation 2 starts at 0x0000022c95591000
ephemeral segment allocation context: none
segment begin allocated size
0000022c95590000 0000022c95591000 0000022c96166da8 0xbd5da8(12410280)
Large object heap starts at 0x0000022de5591000
segment begin allocated size
0000022de5590000 0000022de5591000 0000022de5831280 0x2a0280(2753152)
Heap Size: Size: 0xe76028 (15163432) bytes.
------------------------------
Heap 10 (0000022a55480b60)
generation 0 starts at 0x0000022cd55fc550
generation 1 starts at 0x0000022cd55fc358
generation 2 starts at 0x0000022cd5591000
ephemeral segment allocation context: none
segment begin allocated size
0000022cd5590000 0000022cd5591000 0000022cd5622568 0x91568(595304)
Large object heap starts at 0x0000022df5591000
segment begin allocated size
0000022df5590000 0000022df5591000 0000022df55b1050 0x20050(131152)
Heap Size: Size: 0xb15b8 (726456) bytes.
------------------------------
Heap 11 (0000022a5546df00)
generation 0 starts at 0x0000022d155a5040
generation 1 starts at 0x0000022d155a4f68
generation 2 starts at 0x0000022d15591000
ephemeral segment allocation context: none
segment begin allocated size
0000022d15590000 0000022d15591000 0000022d155bb058 0x2a058(172120)
Large object heap starts at 0x0000022e05591000
segment begin allocated size
0000022e05590000 0000022e05591000 0000022e057421c8 0x1b11c8(1774024)
Heap Size: Size: 0x1db220 (1946144) bytes.
------------------------------
GC Heap Size: Size: 0x6078d408 (1618531336) bytes.
输出结果,可以看到总共有12个堆,其中第0号和第8号托管堆中的大对象堆有异常,从上面的结果里摘出第0号和8号托管堆如下:
------------------------------
Heap 0 (0000022a54cebf90)
generation 0 starts at 0x0000022a555ab848
generation 1 starts at 0x0000022a555ab690
generation 2 starts at 0x0000022a55591000
ephemeral segment allocation context: none
segment begin allocated size
0000022a55590000 0000022a55591000 0000022a55607860 0x76860(485472)
Large object heap starts at 0x0000022d55591000
segment begin allocated size
0000022d55590000 0000022d55591000 0000022d555b3180 0x22180(139648)
0000022a00000000 0000022a00001000 0000022a2f001040 0x2f000040(788529216)
Heap Size: Size: 0x2f098a20 (789154336) bytes.
------------------------------
Heap 8 (0000022a554648d0)
generation 0 starts at 0x0000022c555d3348
generation 1 starts at 0x0000022c555c6300
generation 2 starts at 0x0000022c55591000
ephemeral segment allocation context: none
segment begin allocated size
0000022c55590000 0000022c55591000 0000022c555f7360 0x66360(418656)
Large object heap starts at 0x0000022dd5591000
segment begin allocated size
0000022dd5590000 0000022dd5591000 0000022dd5591018 0x18(24)
0000022e215d0000 0000022e215d1000 0000022e505d1040 0x2f000040(788529216)
Heap Size: Size: 0x2f0663b8 (788947896) bytes.
可以看到,在两个托管堆的大对象堆(LOH)上,分别有一个 788529216字节,约等于752 M大小的数据,这是一块非常大的段,接下来,我们选一个把这个LOH中的内容dump出来。
我们选了Heap8,里面的大对象堆的,第二个Segment来看下,使用!dumpheap命令,指定起始位置和大小,即可输出堆内容。
0:000> !dumpheap 0000022e215d1000 0000022e505d1040
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Address MT Size
0000022e215d1000 0000022a54c87bd0 30 Free
0000022e215d1020 00007ffc7b2bc768 788529179
Statistics:
MT Count TotalSize Class Name
0000022a54c87bd0 1 30 Free
00007ffc7b2bc768 1 788529179 System.Byte[]
Total 2 objects
可以看到,这个堆里面,就两个内容,一个还是Free空闲块,另外一个是一个奇大无比的,大小将近750MB的字节数组🤣,这究竟是个什么东西?可以用!dumpobj,或简写!do,加 /d 参数指定address,来查看内部内容。
0:000> !do /d 0000022e215d1020
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Name: System.Byte[]
MethodTable: 00007ffc7b2bc768
EEClass: 00007ffc7ac651a8
Size: 788529179(0x2f00001b) bytes
Array: Rank 1, Number of elements 788529155, Type Byte (Print Array)
Content: *......Cookie: mstshash=Administr...............................................................................................
Fields:
None
可以看到,这个超长的字节数组里的内容有“.Cookie: mstshash=Administr.”,非常奇怪,这里只显示了这个数组的部分内容,要显示更多的内容怎么办呢,直接使用db命令,加上起始地址,和结束地址。
0:000> db 0000022e215d1020 0000022e215d1020+0n1000
0000022e`215d1020 68 c7 2b 7b fc 7f 00 00-03 00 00 2f 00 00 00 00 h.+{......./....
0000022e`215d1030 2a e0 00 00 00 00 00 43-6f 6f 6b 69 65 3a 20 6d *......Cookie: m
0000022e`215d1040 73 74 73 68 61 73 68 3d-41 64 6d 69 6e 69 73 74 stshash=Administ
0000022e`215d1050 72 0d 0a 01 00 08 00 03-00 00 00 00 00 00 00 00 r...............
0000022e`215d1060 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
0000022e`215d1070 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
0000022e`215d1080 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
0000022e`215d1090 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
0000022e`215d10a0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
0000022e`215d10b0 00 00 00 00 00 00 00 00-00 00 00 00 00 00 00 00 ................
............................................
0n表示十进制+1000表示起始地址加上1000个字符,上面的结果显示了这个字节数组的前1000个字符,可以看到后面起始都是空字符串,只有前面那一段有奇怪的“.Cookie: mstshash=Administr.”字符。
紧接着查看一下,这个LOH的对象的根,使用!gcroot命令,加上地址就可以查看对象的根,看是哪个对象持有了这么大个数组。
0:000> !gcroot 0000022e215d1020
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Finalizer Queue:
0000022bd56b4bf0
-> 0000022bd56b4bf0 System.Net.Sockets.SocketAsyncEventArgs
-> 0000022e215d1020 System.Byte[]
Warning: These roots are from finalizable objects that are not yet ready for finalization.
This is to handle the case where objects re-register themselves for finalization.
These roots may be false positives.
Found 1 unique roots (run '!GCRoot -all' to see all roots).
可以看到,它的根对象在终结者队列里(实现了Finalize方法的对象,都会有一个终结者队列引用它),该对象看起来是在Socket接收请求的方法里。
紧接着我们查看下这个持有这么大的数组的位于终结队列上的对象,还是使用!do命令,
0:000> !do /d 0000022bd56b4bf0
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Name: System.Net.Sockets.SocketAsyncEventArgs
MethodTable: 00007ffc7a392958
EEClass: 00007ffc7a04c968
Size: 456(0x1c8) bytes
File: C:\Windows\Microsoft.Net\assembly\GAC_MSIL\System\v4.0_4.0.0.0__b77a5c561934e089\System.dll
Fields:
MT Field Offset Type VT Attr Value Name
00007ffc7b2a8f78 4000572 268 System.EventArgs 0 shared static Empty
>> Domain:Value 0000022a54cbcad0:NotInit <<
00007ffc7a341e18 4001e20 8 ...et.Sockets.Socket 0 instance 0000000000000000 m_AcceptSocket
00007ffc7a341e18 4001e21 10 ...et.Sockets.Socket 0 instance 0000000000000000 m_ConnectSocket
00007ffc7b2bc768 4001e22 18 System.Byte[] 0 instance 0000022e215d1020 m_Buffer
00007ffc7a369000 4001e23 180 System.Net.WSABuffer 1 instance 0000022bd56b4d70 m_WSABuffer
00007ffc7b2a47f0 4001e24 f8 System.IntPtr 1 instance 22e215d105b m_PtrSingleBuffer
00007ffc7b2b9e10 4001e25 138 System.Int32 1 instance 788529112 m_Count
00007ffc7b2b9e10 4001e26 13c System.Int32 1 instance 43 m_Offset
00007ffc26f9b2c8 4001e27 20 ...lib]], mscorlib]] 0 instance 0000000000000000 m_BufferList
00007ffc7b2a17d0 4001e28 178 System.Boolean 1 instance 0 m_BufferListChanged
00007ffc7a35ba98 4001e29 28 ...m.Net.WSABuffer[] 0 instance 0000000000000000 m_WSABufferArray
00007ffc7b2b9e10 4001e2a 140 System.Int32 1 instance 0 m_BytesTransferred
00007ffc79f67e00 4001e2b 30 ...entArgs, System]] 0 instance 0000022bd56b4b78 m_Completed
00007ffc7b2a17d0 4001e2c 179 System.Boolean 1 instance 0 m_CompletedChanged
00007ffc7b2a17d0 4001e2d 17a System.Boolean 1 instance 0 m_DisconnectReuseSocket
00007ffc7a377b98 4001e2e 144 System.Int32 1 instance 4 m_CompletedOperation
00007ffc7a381690 4001e2f 190 ...PacketInformation 1 instance 0000022bd56b4d80 m_ReceiveMessageFromPacketInfo
00007ffc7a338748 4001e30 38 System.Net.EndPoint 0 instance 0000000000000000 m_RemoteEndPoint
00007ffc7a36ba20 4001e31 148 System.Int32 1 instance 0 m_SendPacketsFlags
00007ffc7b2b9e10 4001e32 14c System.Int32 1 instance 0 m_SendPacketsSendSize
0000000000000000 4001e33 40 SZARRAY 0 instance 0000000000000000 m_SendPacketsElements
0000000000000000 4001e34 48 SZARRAY 0 instance 0000000000000000 m_SendPacketsElementsInternal
00007ffc7b2b9e10 4001e35 150 System.Int32 1 instance 0 m_SendPacketsElementsFileCount
00007ffc7b2b9e10 4001e36 154 System.Int32 1 instance 0 m_SendPacketsElementsBufferCount
00007ffc7a36d520 4001e37 158 System.Int32 1 instance 10054 m_SocketError
00007ffc7b2b76f0 4001e38 50 System.Exception 0 instance 0000000000000000 m_ConnectByNameError
00007ffc7a361d88 4001e39 15c System.Int32 1 instance 0 m_SocketFlags
00007ffc7b2b7aa0 4001e3a 58 System.Object 0 instance 0000022bd56b4bb8 m_UserToken
00007ffc7b2bc768 4001e3b 60 System.Byte[] 0 instance 0000000000000000 m_AcceptBuffer
00007ffc7b2b9e10 4001e3c 160 System.Int32 1 instance 0 m_AcceptAddressBufferCount
00007ffc7b2a47f0 4001e3d 100 System.IntPtr 1 instance 0 m_PtrAcceptBuffer
00007ffc7a33a598 4001e3e 68 ...Net.SocketAddress 0 instance 0000000000000000 m_SocketAddress
00007ffc7b2a44a0 4001e3f 1a0 ...Services.GCHandle 1 instance 0000022bd56b4d90 m_SocketAddressGCHandle
00007ffc7a33a598 4001e40 70 ...Net.SocketAddress 0 instance 0000000000000000 m_PinnedSocketAddress
00007ffc7b2a47f0 4001e41 108 System.IntPtr 1 instance 0 m_PtrSocketAddressBuffer
00007ffc7b2a47f0 4001e42 110 System.IntPtr 1 instance 0 m_PtrSocketAddressBufferSize
00007ffc7b2bc768 4001e43 78 System.Byte[] 0 instance 0000000000000000 m_WSAMessageBuffer
00007ffc7b2a44a0 4001e44 1a8 ...Services.GCHandle 1 instance 0000022bd56b4d98 m_WSAMessageBufferGCHandle
00007ffc7b2a47f0 4001e45 118 System.IntPtr 1 instance 0 m_PtrWSAMessageBuffer
00007ffc7b2bc768 4001e46 80 System.Byte[] 0 instance 0000000000000000 m_ControlBuffer
00007ffc7b2a44a0 4001e47 1b0 ...Services.GCHandle 1 instance 0000022bd56b4da0 m_ControlBufferGCHandle
00007ffc7b2a47f0 4001e48 120 System.IntPtr 1 instance 0 m_PtrControlBuffer
00007ffc7a35ba98 4001e49 88 ...m.Net.WSABuffer[] 0 instance 0000000000000000 m_WSARecvMsgWSABufferArray
00007ffc7b2a44a0 4001e4a 1b8 ...Services.GCHandle 1 instance 0000022bd56b4da8 m_WSARecvMsgWSABufferArrayGCHandle
00007ffc7b2a47f0 4001e4b 128 System.IntPtr 1 instance 0 m_PtrWSARecvMsgWSABufferArray
00007ffc7bd37a60 4001e4c 90 ...m.IO.FileStream[] 0 instance 0000000000000000 m_SendPacketsFileStreams
0000000000000000 4001e4d 98 SZARRAY 0 instance 0000000000000000 m_SendPacketsFileHandles
00007ffc7a9c6318 4001e4e a0 ...tPacketsElement[] 0 instance 0000000000000000 m_SendPacketsDescriptor
00007ffc7b2a47f0 4001e4f 130 System.IntPtr 1 instance 0 m_PtrSendPacketsDescriptor
00007ffc7b2a3820 4001e50 a8 ....ExecutionContext 0 instance 0000022bd56b4ec0 m_Context
00007ffc7b2a3820 4001e51 b0 ....ExecutionContext 0 instance 0000022d155af528 m_ContextCopy
00007ffc7b2a55c8 4001e52 b8 ...g.ContextCallback 0 instance 0000022bd56b4db8 m_ExecutionCallback
00007ffc7a341e18 4001e53 c0 ...et.Sockets.Socket 0 instance 0000022bd56b1430 m_CurrentSocket
00007ffc7b2a17d0 4001e54 17b System.Boolean 1 instance 1 m_DisposeCalled
00007ffc7b2b9e10 4001e59 164 System.Int32 1 instance 2 m_Operating
00007ffc7a357218 4001e5a c8 ...eNativeOverlapped 0 instance 0000000000000000 m_PtrNativeOverlapped
00007ffc7b2a7888 4001e5b d0 ...eading.Overlapped 0 instance 0000000000000000 m_Overlapped
00007ffc7b2b7b38 4001e5c d8 System.Object[] 0 instance 0000000000000000 m_ObjectsToPin
00007ffc7a37cf50 4001e5d 168 System.Int32 1 instance 0 m_PinState
00007ffc7b2bc768 4001e5e e0 System.Byte[] 0 instance 0000000000000000 m_PinnedAcceptBuffer
00007ffc7b2bc768 4001e5f e8 System.Byte[] 0 instance 0000000000000000 m_PinnedSingleBuffer
00007ffc7b2b9e10 4001e60 16c System.Int32 1 instance 0 m_PinnedSingleBufferOffset
00007ffc7b2b9e10 4001e61 170 System.Int32 1 instance 0 m_PinnedSingleBufferCount
00007ffc7a36d1c8 4001e62 f0 ...tipleConnectAsync 0 instance 0000000000000000 m_MultipleConnect
00007ffc7a3846c0 4001e64 174 System.Int32 1 instance 0 <SocketClientAccessPolicyProtocol>k__BackingField
00007ffc7b2b9e10 4001e1d b98 System.Int32 1 static 24 s_ControlDataSize
00007ffc7b2b9e10 4001e1e b9c System.Int32 1 static 40 s_ControlDataIPv6Size
00007ffc7b2b9e10 4001e1f ba0 System.Int32 1 static 56 s_WSAMsgSize
00007ffc7b2a17d0 4001e63 ba4 System.Boolean 1 static 0 s_LoggingEnabled
可以看到,输出的第4列里,有个名为m_Buffer的类型为System.Byte[]的字段,它的内容恰好就是上述我们看到的那个超大数组,里面只有一个“.Cookie: mstshash=Administr.”奇怪的内容。这个m_Buffer看起来是Socket接收数据的缓冲区,为啥有这么大个缓冲区,且里面有这么个奇怪的字符串呢?
继续使用上述相同的办法,分析Heap0,发现结果也是内似。
:000> !dumpobj /d 0000022a00001020
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Name: System.Byte[]
MethodTable: 00007ffc7b2bc768
EEClass: 00007ffc7ac651a8
Size: 788529179(0x2f00001b) bytes
Array: Rank 1, Number of elements 788529155, Type Byte (Print Array)
Content: *......Cookie: mstshash=Administr...............................................................................................
Fields:
None
0:000> !gcroot 0000022a00001020
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.7.3324.0
SOS Version: 4.8.4614.0
Finalizer Queue:
0000022bd56dc878
-> 0000022bd56dc878 System.Net.Sockets.SocketAsyncEventArgs
-> 0000022a00001020 System.Byte[]
Warning: These roots are from finalizable objects that are not yet ready for finalization.
This is to handle the case where objects re-register themselves for finalization.
These roots may be false positives.
Found 1 unique roots (run '!GCRoot -all' to see all roots).
可以相信,如果这个程序继续运行,由于某种奇怪的原因,因为托管堆会再平衡,它会在其它的剩余的10个托管堆可能也会分配这么大的一个数组。
水落石出
再次回到代码中来,作为一个订阅程序的服务端,在接收客户端程序使用TCP协议发送来的订阅信息的时候,为什么缓冲区里有在特殊的,占用空间量很大的“.Cookie: mstshash=Administr.”这种特殊字符呢? 这个字符显然不可能是客户端程序主动发送的。于是在网上找了一下,有人也遇到过这个问题,说是RDP的漏洞,也有人遇到过这个问题。
mstshash may refer to RDP. This is surely an attack (scanning) attempt, but the target should be some sort of rdp vulnerability.......
也就是说,只要有端口对外暴露,网上就有人试图通过扫描,连接该端口并发送信息。查看日志,果然发现,在周六的凌晨时分,有奇怪的IP地址连接过。
[2023-04-24 00:44:18,937] ERROR - accepted socket from 92.63.196.149:64646
[2023-04-24 00:47:29,508] ERROR - 92.63.196.149:64646断开连接
▲来自阿姆斯特丹的问候
再次回到前面说过的,程序接收TCP信息的格式是,“消息长度+消息内容”,首先接收一个4个字节长度的内容,表示后续消息的长度,接收到长度信息之后,就创建一个该长度的byte数组用于存放即将接收到的消息体,直到后续接收到的内容填满整个byte数组长度,然后处理消息,然后接下来处理下一个订阅。
int length = BitConverter.ToInt32(e.Buffer, 0);
if (length > 0)
{
e.SetBuffer(new byte[length], 0, length);
}
一个最直观的解决方法是,对接收的数据的消息长度进行限制,超过长度的直接拒绝处理。
▲当问题很明显的时候
接下来的问题是,这个如此之大的数组是外部传进来的吗?还是我们自己根据接收到的消息头里的长度来创建的,用来保存后续的内容。外部传进来的似乎也有可能,但谁会传进来一个超过750mb的,只有头部有点字符串,后面都是空的byte数组呢?所以有可能是程序自己根据消息头里的长度来创建的,用来接收后续收到的消息体信息。于此同时,我们又找了几个之前在测试环境内存过大时,获取的dump文件进行了分析。
0:000> !dumpheap 00000004ffff1000 000000057d216a90
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.8.4110.0
SOS Version: 4.8.4614.0
Address MT Size
00000004ffff1000 00000000004e7200 30 Free
00000004ffff1020 000007fef5cfaaa0 2099403371
Statistics:
MT Count TotalSize Class Name
00000000004e7200 1 30 Free
000007fef5cfaaa0 1 2099403371 System.Byte[]
Total 2 objects
0:000> !DumpObj /d 00000004ffff1020
The version of SOS does not match the version of CLR you are debugging. Please
load the matching version of SOS for the version of CLR you are debugging.
CLR Version: 4.8.4110.0
SOS Version: 4.8.4614.0
Name: System.Byte[]
MethodTable: 000007fef5cfaaa0
EEClass: 000007fef5e66c78
Size: 2099403371(0x7d225a6b) bytes
Array: Rank 1, Number of elements 2099403347, Type Byte (Print Array)
Content: {"MsgType":3,"Data":"600109"}....{"MsgType":3,"Data":"601138"}....{"MsgType":3,"Data":"601108"} ...{"MsgType":3,"Data":"000562.S
Fields:
None
0:000> db 00000004ffff1020 00000004ffff1020+0n200
00000004`ffff1020 a0 aa cf f5 fe 07 00 00-53 5a 22 7d 00 00 00 00 ........SZ"}....
00000004`ffff1030 7b 22 4d 73 67 54 79 70-65 22 3a 33 2c 22 44 61 {"MsgType":3,"Da
00000004`ffff1040 74 61 22 3a 22 36 30 30-31 30 39 22 7d 1d 00 00 ta":"600109"}...
00000004`ffff1050 00 7b 22 4d 73 67 54 79-70 65 22 3a 33 2c 22 44 .{"MsgType":3,"D
00000004`ffff1060 61 74 61 22 3a 22 36 30-31 31 33 38 22 7d 1d 00 ata":"601138"}..
00000004`ffff1070 00 00 7b 22 4d 73 67 54-79 70 65 22 3a 33 2c 22 ..{"MsgType":3,"
00000004`ffff1080 44 61 74 61 22 3a 22 36-30 31 31 30 38 22 7d 20 Data":"601108"}
00000004`ffff1090 00 00 00 7b 22 4d 73 67-54 79 70 65 22 3a 33 2c ...{"MsgType":3,
00000004`ffff10a0 22 44 61 74 61 22 3a 22-30 30 30 35 36 32 2e 53 "Data":"000562.S
00000004`ffff10b0 5a 22 7d 20 00 00 00 7b-22 4d 73 67 54 79 70 65 Z"} ...{"MsgType
00000004`ffff10c0 22 3a 33 2c 22 44 61 74-61 22 3a 22 30 30 32 37 ":3,"Data":"0027
00000004`ffff10d0 35 36 2e 53 5a 22 7d 1d-00 00 00 7b 22 4d 73 67 56.SZ"}....{"Msg
00000004`ffff10e0 54 79 70 65 22 3a 33 2c-22 Type":3,"
客户端订阅的内容就是右边这样的字符,订阅的消息对象有两个字段,分为MsgType订阅类型,和Data订阅内容,这些内容通过Json序列化后发送。查字符串对应的十六进制字符可以得知,左括号和右括号的十六进制分别为“7b”和“7d”,我们取如下的块来查看:
▲堆积了大量请阅请求的缓存byte数据,看起来消息长度和消息体正常
可以看到,在"7b"之前有四个字节"1d 00 00 00",转换一下就是"00 00 00 1d",这是十六进制表示,换成10进制就是29,表示后面的“7b”和“7d”所表示的范围有29个字符,对应的内容就是 {"MsgType":3,"Data":"601138"} 恰好就是29个字符,这个消息长度和消息体是一致的没问题。这里看到的是,有一个2G的byte数组,其开头处的内容是正常的客户端订阅的股票信息,这些信息没有被及时处理,且从格式看是正常的“消息长度+消息体”的格式。
但在另外一个dump文件里却不是这样,如下,可以看到这个消息体前面没有长度信息。
▲异常情况下,消息体之前的消息长度信息丢失,从而有可能错误的将消息体的前4个字节,比如 {"Ms 解析为消息长度
那是不是说明,消息长度和消息体的接收顺序发生了错乱,有些订阅只有消息体没有消息长度。所以问题就聚焦到了客户端订阅信息时发送订阅信息的地方,和服务端接收订阅信息时解析消息的代码。
public void Send(byte[] data)
{
if (null != data && data.Length > 0 && null != so)
{
try
{
so.BeginSend(BitConverter.GetBytes(data.Length), 0, 4, SocketFlags.None, SendCallback, so);
so.BeginSend(data, 0, data.Length, SocketFlags.None, SendCallback, so);
}
catch (Exception e)
{
LogMsg(e.Message + e.StackTrace);
CloseSocket();
}
}
}
可以看到,消息的长度和消息的内容是分开发送的,在多线程环境下,如果多个线程同时发送,服务端可能会先收到消息体,而不是消息头。如果服务端首先收到的是消息体,那么它首先读取这个消息体的前4个字节,作为消息的长度,这时就会出现问题,如果一个字符串的前四个字节转为int的话,可能会是一个很大的数,这就会导致创建一个非常大的byte数组来等待消息体填满,而消息体可能没有那么长,这样服务端的程序就会一直等待在那里,直到后续的消息把这个大数组填满,才能处理下一个请求。
知道了问题出在订阅时消息体长度和消息体分开发送,在多线程环境下能会出现消息体先到达,而消息大小后到达的情况后,这种情况就很容易重现了。可以在多线程环境下发起订阅请求,比如如下:
foreach (var symbol in dataRecorder.RecordSymbols)
{
subscriber.SubscribeSymbol(symbol);
}
改为多线程,
Parallel.ForEach(dataRecorder.RecordSymbols, new ParallelOptions { MaxDegreeOfParallelism = 8 }, symbol =>
{
subscriber.SubscribeSymbol(symbol);
});
多线程环境下,由于消息头和消息体的顺序可能发生颠倒,从而很容易把DataFeedGateway的内存搞满。
解决方法很简单,就是在订阅的时候,把消息长度和消息体放在一个byte数组里,一次性发送,而不是分两次发送。这样就能保证服务端收到的订阅内容里消息头部大小字段永远在消息体之前。另外一个地方就是服务端在解析消息体长度的时候要做校验。万一那个客户端发送了一个超级大的数据,就直接丢弃。
总结
按照前面发射火箭失败的清零评审格式,对于使用WinDbg发现内存爆炸的原因,总结如下:
2023年5月,我司组织召开DataFeedGateway内存暴涨的归零评审会议。评审专家组经评议,一致认为DataFeedGateway的内存暴涨问题定位准确、机理清楚,在测试环境中故障复现,采取的改进措施经验证有效,可以归零。DataFeedGateway于2022年5月12日在运行过程中,突然内存暴涨,从而影响客户交易,重启程序后问题解决,并长期没有复现。然而在2023年3月20日,该问题又复现且当天内存占用过高问题在程序重新启动后不久仍然再次复现。当天收盘后,我司程序员迅速开展故障分析工作,定位故障原因、分析故障模式和故障机理。通过对DataFeedGateway代码的详细分析,开展了全面的仿真模拟和一系列针对性的压力测试,并使用各种性能分析工具进行分析,查明了内存占用过高的原因和机理。内存暴涨的原因定位于客户端在向DataFeedGateway发送订阅数据的时候,消息大小和消息体分开先后发送,在多线程的情况下,会导致DataFeedGateway首先接收到了消息体,而不是消息大小。首先接收到了消息体误认为这是消息大小后,在读取消息体的前4个字节时,错误的得到了特别大的数字,在得到特别大的消息长度时,没有对消息长度进行限制,从而创建了一个特别大的byte数组用来接收后续的消息体,导致程序占用大量内存。且由于后续的消息体不可能填充满这么大的byte数组,从而导致无法接收和处理后续的订阅。针对故障原因和机理,我们采取了对消息大小和消息体合并发送,并且在服务端收到订阅信息后,对解析到的消息大小进行校验,并且使用对象池对byte数组进行了缓存等一系列优化和改进措施。改进措施经过仿真模拟和压力测试,完全解决了内存偶尔暴涨以及之前出现过的偶发的订阅失效的问题。感谢老板在归零过程中对我们的忍耐,感谢用户的信任和理解。后续将迅速落实故障改进措施,不断增强代码安全意识、心怀敬畏,确保后续工作中不会出现类似错误。
参考:
- https://isc.sans.edu/diary/Random+Port+Scan+for+Open+RDP+Backdoor/24422
- https://serverfault.com/questions/1004144/whats-the-meaning-of-this-binary-sequence-arriving-at-my-http-server
- https://blog.csdn.net/u010033786/article/details/126275465
- https://www.bilibili.com/video/BV1a24y1q7Bp/
- https://anduin.aiursoft.com/post/2021/9/24/the-method-to-find-the-root-cause-of-the-metaphysical-problem-the-method-of-forced-debugging
- https://stackoverflow.com/questions/25435949/in-windbg-how-to-get-the-whole-content-from-do-command