往事手游

      顾煜，就职于腾讯引擎技术中心，是《天涯明月刀OL》的技术总监。《BUG往事》原文发表于其知乎专栏“游戏开发随笔”。作者用诙谐幽默的语气讲述了作为程序员与其天敌“BUG”斗智斗勇的故事。

      该文文笔妙趣横生，即使你完全不懂程序员的那些语言也能从顾煜的文字里读出一点儿“老子不信斗不过你”的不服输的劲儿。触乐将全文转载、编撰录入以饕读者。

      翻出一篇老文，辛苦写给公司内刊，貌似最后没有发表……润色一下，发出来，纪念那些年修过的奇葩bug们。

      记忆中有很多次了，几个程序员朋友聊天，聊着聊着，就聊到自己遇到过的bug。然后大家开始口沫横飞交流那些或诡异或神奇的bug，谈论自己当年是如何搞定bug或是被bug搞定。

      正好看见Gamesutra上也登了篇Dirty Coding Tricks，发现老外也有这个癖好，原来天下程序员本一家。一路走来，程序员的成长，便是一路刀光剑影，与bug斗个你死我活。了解别人的Debug过程，或是回忆一下自己Debug的时候思路，也是很有意思的事情，值得定期总结。

      下面分享一下自己遇到过印象深刻的bug。

      ■ 靠不住的OS：Memcpy的传说

      做一个PC项目的时候，凶猛的测试兄弟把Winxp 64单独列出来，作为一个测试平台，然后我们的噩梦就开始了。游戏在Winxp 64上面频繁Crash，经常在更新Octree的时候访问到空指针，但逻辑上来看那个指针不可能是空的。Crash位置很随机，到处都有，通常都是玩了一个小时在一个莫名其妙的地方Crash。

      第一反应就是那些地址被非法访问，可能是某个错误的指针指向那里，往里面写了不该写的值。于是我根据最常Crash的地址设下数据断点，试了好几天，从来没有断下过，Crash还是依旧。然后同事试图加上大量的保护代码，判断一个指针是不是空指针后才使用，很好的降低了Crash机率，但偶尔还是会有。想想问题根源没有找到，降低Crash概率只是让自己更难修bug，而且访问Octree也比较多，乱加保护会影响性能，我一狠心又把保护代码全去掉了。

      Takeaway: 不到万不得已，不要用保护代码掩盖Bug，它只会让你的日子更难过。

      来回几轮搞下来，根据某次比较靠谱的Crash Callstack，怀疑到了memcpy。memcpy是个老同志了，兢兢业业地忙碌在各个程序里，负责搬运数据很多年，工作绩效有口皆碑。它有什么问题呢？它还能有什么问题呢？

      为了保证多线程能同步并行执行，我们程序中有个很大的memcpy，把一块Octree从后台用memcpy复制到前台的工作buffer。当然这个做法的设计优劣不在此讨论，存在即合理，2007年，多线程引擎我们还不是那么擅长搞。

      既然有怀疑，就要捉奸。我做了试验，在memcpy后面直接加一个循环，逐字节比较源数据和目标数据，有时候居然会不相等… 这个可颠覆了我的世界观。我试图写了一个函数，里面就一个循环，逐字节复制数据，然后把所有的memcpy全替换成这个函数，果然不Crash了。但显然这是不行的，速度太慢了。

      既然有了点线索，就可以试图简化bug重现条件了。我不能每次都花一个小时去运行游戏，寻找那一次crash。我在游戏load起来，开始走主循环后，加了一个死循环，不停用memcpy复制一块内存，然后比较源数据和目标数据。源数据里面没有0，都是1-255的值，可是运行几十秒以后目标数据居然有0。这样，我们成功地把重现一次bug的平均时间从一个小时降低到一分钟。

      我们的怀疑从3d代码转移到多线程，在进入那个死循环之前，我们设下断点，把其他无关的线程全部都Freeze，只有那个线程会运行。这样，任何多线程的干扰全部排除，memcpy在一个理想的环境中欢快的运行，但memcpy还是会出错。

      继续简化，我单独写一个小程序，里面只做死循环和memcpy，来判断是不是OS的问题（实在是走投无路了）。试验结果是，Winxp 64没有问题，memcpy始终如一地正常工作着（本该如此）。 可是某一次，当我们的游戏在后台运行的时候，再启动这个小程序，居然memcpy又出问题了……无语了，原来我们的游戏还能万里追杀，跨进程搞垮OS下面的其他进程。

      山穷水尽疑无路，我无奈下单步跟踪了一下memcpy的汇编代码，上来有两句：

      也就是说，memcpy上来看有没有设置__sse2_available，这个值估计是CRT库里面设的，如果有SSE2就执行sse优化的memcpy，没有就跳到Dword_align那里执行普通版本的流程。我开始怀疑是不是我们的游戏里面对系统做了点什么手脚，导致在__sse2_available允许的情况下，优化的代码会执行出错。游戏的代码规模实在太大，又用了n个中间件，我无力一一查看，且我也看不懂SSE代码（哎呀好羞射），就随手做了个试验，在那句判断的地方，通过Debugger把__sse2_available的值改成了0。从此memcpy再也不出错了。

      所以最终的解决方案是，Win64下，我在游戏一开始初始化的地方，加上谜一样的初始化代码：

      这样memcpy就永远使用不做sse2优化的代码了。

      memcpy不使用sse2后会不会有性能问题？经过测试，发现问题不大，对于频繁调用的少量数据复制，memcpy不太能从sse2里面得到多少好处。对于大量数据的复制，我们用得也不多，profile了一下，没有发现明显的瓶颈，无视了。这事情也可以从反向理解，由于游戏规模太大，各种多线程和GPU/CPU同步，导致任何一点的效率损失，可能不会扩散到整个游戏，被其他同步和等待吸收掉了…我真是一个好程序员，能想到这么好的理由说服自己。

      对游戏跨进程影响其他程序的memcpy，实在没能力解决了，Winxp 64是一个太小众的环境，用户要么用Winxp 32, 要么用Vista 32/64，市场占有率很低，我们也算仁至义尽了。

      可得结论：Winxp 64靠不住（其实问题还是应该出在我们内部，不过其他OS都没问题，就赖在它身上了。）

      Takeaway: 首先，你要有一个有耐心的老板，才能给你时间去查这么奇怪的Bug。

      为了达成目的，我们要不择手段

      ■ 靠不住的SDK：OutputDebugString

      话说当年开发Splinter Cell 4，使用的还是XBOX360的Alpha kit。微软早期的360 Kit，全不像后期的Kit，后期kit长得和主机差不多。而当时的KIt，是用一个很大的Power Mac G5，换上一块ATI显卡，再刷上MS的固件，连马甲都不穿一件就出来见人了。

      Xbox 360开发SDK，早期bug一大堆，比如预编译头文件太大了，编译器抱怨说预编译头文件预留内存不够，这个好办，加上/Zm512编译选项即可。加上，编译，没用？！只好写信去MS问，他们说，哦，原来如此啊，今天天气真好，哈哈哈哈，请等待下一次更新，谢谢您汇报云云……虽是MS的bug，可是我也不能等着他修复才工作，只好手动拆分预编译头文件，把很多内容放在预编译头文件外面，预编译头文件就会变小，编译就可以顺利通过了。

      扯远了，回头来说这个OutputDebugString的问题。

      360有3个cores，每个core有2个Hyperthreads，总计6个线程，我们的游戏在逻辑线程、声音线程和渲染线程外，还开了3个辅助线程，用自己写的Thread Pool管理系统来管理这些线程，初始化的时候就是一个循环把每个线程创建出来。

      这个bug的表现现象就是加载失败，程序僵死。团队当时有几十个测试人员，每天打游戏八小时，从没碰到过游戏加载失败情况。但是开发人员这里就有很低概率会加载失败，表现情况为用VC启动游戏，然后过一会加载屏幕就僵死不动了。

      开发人员往往过了5分钟还没在电视上看见游戏画面才知道游戏又挂了，重现概率是每个程序员每一到两天碰到一次。我们担心这是线程管理系统内部的问题，就让每个开发人员碰到这种情况不要急着重启动，把现场给我看一下。每次僵死的时候都是在系统内核死锁，Callstack也没有有价值的信息，基本都是在创建每个线程的时候打印一句语句的时候就内核就死了。在接下来一周里，我试图在线程管理系统内部加一些日志输出，每次重现bug的时候查看日志，也没有找到更好的线索。

      重现概率实在太低，不好调试，于是我试图用简单的程序片段来重现这个bug。因为都是创建新线程时候死锁，第一个想到的就是写一个小程序，直接一个死循环，创建线程，打印日志，然后杀掉线程，重复再做。果然能够重现bug，程序运行1分钟以后，就死锁了。同样的现场，还是在OutputDebugString内部死锁了。难道bug不是在线程库，而是在OutputDebugString内？

      Takeaway: 不要轻易相信你看见的表层问题，问题可能在别处。

      正好那些天有个微软360开发组的人员在我们组Onsite支持，于是他带着大量的360 Sdk的符号库(Symbol)来帮助调试，因为他不是做这一个模块的，最后也没有什么结果。最后他把我的小程序发回微软，找到内部开发人员处理，这比我们直接走正式support流程快很多。

      Takeaway: 隔离问题，编写更小的测试案例，便于和别人沟通交流，寻求帮助。

      一天后，微软发回Email，说这是内部的Bug，请无视，不会影响Release版本，是Debug协议上的问题。

      可得结论：微软靠不住。（开玩笑，请微软公司不要追杀）

      ■ 靠不住的系统组件：Vista和Speech Recogition

      我们游戏使用了语音识别，使用了DirectX里面的XAudio来采集声音。Windows Vista里面有一个语音识别的组件，启动那个程序，然后玩我们的游戏，玩了一段时间，因为没有使用麦克风，那个程序会自动关闭使用麦克风，然后我们的游戏就Crash了。又是一个跨进程的奇葩Bug。

      从现场来看，Crash在使用XAudio的库代码里面。看不出什么线索，最后发现在日志里面，Crash前一会儿，XAudio的dll被Unload掉了。Vista那个语音组件很强悍，也会跨进程追杀大法，在自己进程把我的进程dll给Unload掉了。

      虽然遇事先要怀疑自己的代码有问题，但这个情况太匪夷所思，所以我试图推卸责任，我跑了几个其他DirectX程序和Demo，但凡用到XAudio组件的，在Vista Speech Recognition这一大招前无一幸免，全部Crash。

      问题不在我们这里，但是作为一个职业杀虫人，我有着“只解沙场为国死，何须bug裹尸还”的觉悟，决定还是要想办法搞定它。

      我猜这个组件退出的时候，广播了点什么消息，让系统所有进程去卸载这个Dll。我找了一个微软提供的库Detours Express，专做Hook API的勾当。它会反汇编API的入口代码，然后动态替换入口，插入jmp指令去执行我们自己的函数。先看了文档，搞懂这个东西怎么用，然后猜测是一个OS内部的消息导致Unload DLL，我们就拦截了RegisterWindowMessage。一通翻箱倒柜，啥有意义的东西都没发现。

      再用spy++来拦截消息，发现有一个MSUIM.msg.rpcsendreceive的消息面目狰狞，很可疑。就在收到这个消息以后，Dll就被Unload了。于是我们用Detours截住这个消息，直接返回。

      以为搞定了，但结果还是不行，有几条别的消息也会触发Unload Dll，我一一用Detours拦截返回。拦截的消息越来越多，看来不是个解决办法。于是我怀疑我们没有拦截到正确的消息，怀疑OS启动的时候便注册了一堆内部用的消息，而不是在运行进程的时候才注册。那些消息里肯定有我想要的，我便异想天开地Hook了User32.dll，拦截下所有消息，在安全模式下把修改过的user32.dll覆盖原来的文件，然后满怀希望的重启动Vista的时候。结果不出所料的蓝屏了……User32.dll是凡人能随便碰的吗？这不是一个User friendly的库，应该改名叫God32.dll。

      这个bug搞了1周，最后才想到最基本的道理，说不定只是Dll内部引用计数被清掉了，所以系统就卸掉Dll了。当Vista语音组件Unload XAudio的时候，系统去看看XAudio库有没有什么别人引用，结果发现居然没有，那就顺手清理了。就像地上有100块钱，你东张西望，发现没有人宣布拥有那张钱，没有一点点犹豫，你随手就把它放进了裤兜，进行了回收。嗯，就是这样的，我喜欢比喻这种修辞手法。

      理论上创建XAudio设备的时候没有做什么额外的加Dll引用计数的事情，怀疑是MS的bug，创建D3D设备、DInput设备的时候都不需要做什么特别的事情的，但他们的引用计数都没有问题。

      于是我恶搞了一下，在初始化XAudio完成以后，手动做了一次LoadLibrary，把XAudio2_1.dll强行Load一遍，相当于自行增加了引用计数。于是再无Crash。

      从此我们的游戏，在Vista 32上过上了幸福的生活。

      可得结论：Vista靠不住

      Takeaway: 不知道该说什么了，这个bug太奇葩了。

      ■ 性能的迷思

      临近最终版本发布的时候，测试人员发现一个问题，当在Vista上连续打游戏过7关以后，游戏帧数一下子变成原来一半了。大家觉得很诡异，都不相信，之前整天玩游戏都没问题的，于是责令测试人员再重现几次，否则拖出去刨坑埋了。我也没当回事，继续调试别的bug。结果他们测了几遍都是这种情况，看来我必须花点力气看看了。

      先编译了一个Profile版本，有大量的Profile代码，可以用我们自己做的工具看Profile结果。跑游戏，一个小时后顺利重现之，按下快捷键，截下一段性能分析数据，打开工具就开始分析。显示结果是在某个线程的声音处理函数里面特别慢，占了20多ms，找来做声音的程序员，让他也去帮忙看。自己继续研究，发现那个声音函数简单，估计最多1-2ms了，绝对不会有问题的。

      于是开始怀疑多线程的问题，之前有过类似bug，在加载关卡的最后一小段时间，音乐和语音会很卡，音频程序员查不出原因。后来我发现声音线程根本分配不出内存，声音线程的内存分配器和主线程共享，通过Critical Section保护着。声音线程进不了Critical Section，因为主线程那时忙于加载，正在疯狂地分配内存，导致声音线程被无法分配所需资源。我又不能调低主线程的优先级，否则加载速度会受到很大影响。最后解决方案是为声音线程单独开了一个内存分配器，不和主线程抢了。会不会是这个分配器有问题呢？我验证了很久，把那个声音线程的内存分配器换成绝无性能问题的版本，还是有问题，估计不是内存分配的问题。

      也许是那个很慢的声音处理函数里面有些资源被别的线程占了，导致在那里傻等，最后耽误了系统所有线程的同步，使帧数下降。有了想法我就开始验证，我在那里的每个多线程同步操作里都加上了Profile代码，继续花了一个小时重现bug，并检查Profile结果，发现那个线程就是慢，没什么特别原因，每个Critical Section都很快就过去了，也就是说，没有哪一个部分特别慢，是整个函数被均匀地拖慢了。

      忙了几天，死去活来，找不到线索。领导决定游戏还是照样发布，我继续看这个问题，准备在Patch里面修正这个bug。

      在一次次重现中，又简化了重现方法，我发现只需要顺序进入那几关，不需要把每一关都打过去的，所以我用作弊码直接完成每一关，重现一次 bug的时间缩短到10分钟以内了。

      看来自己的工具是搞不定这个问题了，请出Intel Vtune来收拾它。公司比较抠门，不肯买Vtune，只好申请了评估版，一个月试用期，应该够搞定这个问题了。用Vtune Profile了几次，每次拖慢的函数都不一定，而且里面真没什么特别的地方。

      又郁闷了两天，某天看着Vtune里面红红绿绿的代表线程忙碌状态的条条，突然发现有一个线程条全是密密麻麻的红条，其他线程的红蓝条相对稀疏一点。开始猜想，是不是有某个线程太忙了，导致抢了所有的时间片，让其他线程都没机会拿到时间片。有了理论依据，大胆求证一番，重现一次bug，帧数很低了以后，断下游戏，把系统里面的n个线程用二分法，Freeze一半，再运行，看帧数，然后恢复一半线程再跑，来回几次，终于发现当某一个线程恢复以后帧数就很低了，其他线程开关都没关系。关掉那个线程游戏马上全速欢快跑开了。再恢复运行那个线程，又是老样子。

      找到了嫌疑目标后，我全力追查这个线程是如何创建的。先在所有创建线程的地方加上日志，输出线程 id，重现bug后找出那个问题线程，然后对照线程 id的日志，试图找出这个线程创建的地方。结果很杯具，那个线程根本就不是我们自己程序创建的。也就是说，OS偷偷帮我们创了一个线程。这个就比较难查了，线程创建的时候我又没法设断点，也不知道系统内部用什么函数去创建线程，无法用Detour去Hook API。

      转机出现在Intel的Thread Profiler，照例又是一个月评估版。Thread Profiler可以显示出创建这个Thread的Callstack，虽然不是特别准确，不过已经是很有用的信息了。我发现那个线程创建的时候Callstack里面有Winhttp之类的函数。

      继续转移战场，看Msdn上介绍的Winhttp系列函数，然后搜索整个项目里面所有用到Winhttp系列函数的地方。应该是我们调用Winhttp的时候方法不正确吧，我猜。好在项目里面用的Winhttp系列函数也不多，每个地方读一遍代码，似乎都没问题。继续想，会不会是中间件的问题，我们用了一个其他分公司开发的网络组件，那个组件没有包含在项目里面，只是弄了个lib过来。我连忙找到那个组件的源码，一搜Winhttp又一大堆，一个个看，也都貌似正确。

      既然是连续玩n关才出问题，可能和什么资源泄露有关吧？我恍然大悟，注意看Winhttp 句柄的生命周期，发现那个中间件，在Xbox360版本上正常释放了句柄，可是Win32上就没有……

      没什么好说的，WinHttpCloseHandle伺候，问题迎刃而解。修正这个bug耗时2周，一路杀到声音、内存管理、网络模块，中间还顺手修复了无数其他bug，最后终于将其正法，改动只是一行而已。

      可得结论：中间件靠不住。