记一次艰难的 debug 历程

五一前，我遇到了一个非常难缠的 bug ，前后花了两天时间才把它解决。其刁钻程度，可以列入我职业生涯的前三，非常值得记录一下。

问题发现在节前两天，很多同事都请了假，我也打算好好休息一下，陪孩子玩几天。就在我例行更新游戏项目的仓库后，突然发现程序崩溃了。一开始，我并不以为意。因为我们的游戏是用 Lua 为主开发的，并不需要在更新后重新编译。我大约一周才会构建一次项目。或许这只是因为我太久没有 build 了，所以我随手构建了一下。但问题依然存在，只不过发生的概率偏低，大约启动三次有一次会出问题。这不寻常，因为我已经很久没见过 Segmentation fault 了。

我们的游戏引擎是专门为手机设计的。为了开发时可以实时关注在手机上的效果，我们不像别的游戏引擎那样，开发时在开发机上跑一个 Windows 或 Mac 版本，只在需要的时候输出一个手机版。我们用 C++/C++/Obj-C 编写了引擎的内核，编译了一个 iOS 上的 App ，在引擎中内置了一个虚拟文件系统。开发时，在开发机上运行一个叫做 fileserver 的进程，把开发机本地的一个目录映射到虚拟文件系统上。这样，手机上的引擎内核在运行时，就会直接读取开发机的目录，我们在开发机上所做的任何修改，就能即刻反应到手机的 App 上。

手机上运行的引擎内核，是项目组统一定期编译发布的，一般我并不自行编译。这次崩溃的是我本地的这个 fileserver 进程。它其实并不运行任何游戏业务逻辑，只是以一个简单的协议向引擎内核提供 Lua 代码和资源而已。虽然它还会做一些更复杂的工作：例如运行时调试手机上的 Lua 程序、按需编译本地的 shader ，贴图、模型、动画等资源，但这次崩溃发生在启动阶段，似乎还未有涉及这些。

奇怪的是，整个项目组只有我一人的开发机出现了问题。调试工作看起来必须我来做了。

fileserver 本身也是 Lua 编写的，只依赖了少量的 C 模块。一开始我觉得几分钟就能查出来，但开始 debug 一个小时后，我意识到问题没那么简单。

首先，我日常运行的是去掉调试信息的 release 版本。因为这个程序已经稳定运行很久了，没想过需要在 C 级别调试它。当我重新编译一个带调试信息的 debug 版本后，几乎就不崩溃了。（从 1/3 的出现概率降低到了 1/20 以下）

我检查了距离上一次稳定运行的版本，最后引发 bug 的提交只是简单的修改了几行看起来完全无害的 Lua 代码。当我试图在相关 Lua 文件中插入几行 log 后，bug 消失了。甚至我只要插入一行完全无副作用的 lua 代码，例如 local x = 1 ，bug 也会消失不见。我迅速就放弃了这种调试方法，开始思考背后的原因。

为什么 bug 只在我的机器上出现，而项目组那么多开发机都没遇到？一个比较明显的区别是，我开发用的 mingw64 ，而其他人使用的是 vc 构建项目。但随后，另一个同事尝试在他开发机上用 mingw 构建，还是未能重现。他怀疑我的 windows 开发环境有所差异。正好我的 windows 提示要升级，我便重新重启系统，顺便冷静了一下。

问题依旧。我排除了开发环境有问题的念头，毕竟之前几个月都是正常的，且我用 git 回退了几个 commits 反复比对确定问题就是最近发生的。即使新更新的 Lua 代码再无害，它也确实改变了程序的行为，偶发的 Segmentation fault 是事实，一定是在某种条件下，C 代码访问了无效的内存，这一定有原因，我不能视而不见。至于增加一行无害的 Lua 代码就能掩盖问题，我只能解释为不同长度的 Lua 代码，在 parser 阶段行为有微妙的不同，这种不同会改变 parser 阶段 lua gc 的时机。

我们的引擎基于 ltask 这个多线程库。它十分类似 skynet ，但更简单一点，同时我针对客户端做了一些不同的优化。我们的程序是多个 Lua 虚拟机并行运行的，这是导致这个 bug 概率出现的原因。我怀疑最终崩溃和 lua gc 有关，所以尝试在启动时关闭了几个虚拟机的 gc ，果然就不崩溃了。

因为最近更新了 lua 5.4.5 rc2 ，所以首先应该排除 Lua 升级的影响。回退 Lua 版本后，问题依旧。而且我认为如果是 Lua 本身的问题，崩溃应该更频繁一些。这明显而多线程相关，和 Lua 无关。

是否有可能是 ltask 隐藏已久的问题被触发了呢？我觉得有可能，毕竟它是一个多线程框架，并发代码很容易滋生 bug 。但另一方面，我又觉得问题出在 ltask 里面的可能性很小。因为它已经两年没做过大的修改了，一直在稳定运行。这次崩溃的 fileserver 是一个业务非常单一的程序。我们的游戏引擎同样运行在 ltask 之上，本身要复杂得多，却毫无问题。

或许，利用 git bisect 确定引发 bug 的 commit 可能会有更多线索。

前面提到，有一个 commit A 在我的机器上直接引发了这个 bug 。但这个 commit 看起来完全无害，它甚至不会在 fileserver 启动阶段运行（属于渲染相关代码）。所以 bug 一定在此之前。我先简化了 commit A 中的大部分修改，只保留了几行 Lua 变更确定能引起问题，重新生成了一个 patch 。然后开始向一周前做 bisect 。每次 bisect 后，就重新 cherry-pick 回新做的 patch 做验证。就这样，定位到三天前的另一次提交 B 引发了问题。

这个 commit B 是同事优化了虚拟文件系统的批量文件读取协议。感觉这次有点接近了，因为它会影响 fileserver 的工作。值得一提的是, 我们的引擎内核的 bootstrap 过程相当复杂。这是因为虚拟文件系统 vfs 本身也是 lua 编写的 ltask 服务，lua 代码却保存在 vfs 中。这就有一个先有鸡还是先有蛋的问题。bootstrap 本身也是 lua 编写的，它还需要有能力自己更新自己。

bootstrap 一开始并不运行在 ltask 中，它需要自举得到一个简易的 vfs 模块，然后通过这个 vfs 模块和 fileserver 通讯，获取最新版本的 bootstrap 代码，如果发现不同，则把自身更新后以新版本再运行一次。然后，ltask 框架被加载进来，并替换掉 bootstrap 用的那个简易 vfs 模块，正式更替为 ltask 自身的一个服务，供后续代码运行时使用。

由此可见，bootstrap 可能被反复执行，且它所属的虚拟机在线程间不断迁移。任何对 vfs 模块的修改势必对整个自举过程有所影响。

仔细检查过 commit B 后，我依然认为它是无害的。只是增加了若干行 Lua 代码。但即使不运行这些新增加的代码，仅仅只是增加代码本身，就足以引起 bug 了。我又裁剪了 commit B 和之前 commit A 一起合并了一个足以引发 bug 的新 patch ，继续用 git bisect 向前回滚。每次回退后都把 patch 打上测试。

同时，我改写了 fileserver 的启动代码，去掉尽量无关的业务，只可能保留引起 bug 的模块。做过一番尝试后，甚至增加了 bug 出现的概率（大约 1/2 的几率出现），如果不出现问题，也可以迅速正常退出，这样可以方便我自动化测试。

当我回滚到 2 月的引擎版本时，我意识到这是一个效率很低的 debug 方案（即使我已经用脚本把测试过程自动化了）。而且难以为继。我已经累积了好几次可能引起 bug 的修改，但它们都是普通的 Lua 代码，表面上完全无害。但缺少任一修改， bug 都会消失不见。真正的原因还是不见踪迹。而我这样不断退回去，总会到一个版本无法正常运行（因为要打太多后来的修改 patch 了）。

这个过程虽然没有找到问题，但至少我确认了几点：

1. bug 已经潜藏很久了，只是这几个月一系列的（无关）修改才暴露出来。
2. 直接引起崩溃的是 Lua 虚拟机所管理的内存被意外修改了，导致 lua 代码的崩溃。多发于 lua gc （因为 gc 会遍历虚拟机的数据），少数情况崩溃在 lua 的其它运行过程。
3. 这是一个并发相关的 bug 。

最后一点是我尝试修改 ltask 的配置中发现的。默认我会为 fileserver 开启 8 个工作线程，而减少工作线程数量后，bug 就消失不见了。这可能也是同事机器上无法重现的原因。我的开发机没有安装云壳，而同事的开发机都运行有一个叫作云壳的后台监控程序。它经常占满一个 cpu 核心，这可能导致实际运行 fileserver 时并发量不足。

另外，我发现了 ltask 最近一次小修改也会干扰 bug 。上个约，同事建议我在 windows 上用 SRWLOCK 代替 CRITICAL SECTION。这固然是一个无关紧要的小修改。但当我回退回 CRITICAL SECTION 版本后， bug 消失了。这佐证了 bug 是并发引起的。也能说明为何我在 C 代码中添加几行 log 也可能让 bug 消失不见，更别说我开启 gdb 调试时就碰不上它了。

五一假期前的最后一天，我陷入了困境。只要稍微修改一下 Lua 代码，崩溃就可能消失不见。但确确实实，几行分散在多个文件，多个虚拟机内的 Lua 代码就有概率引起 Segmentation fault 。用 gdb 调试时 bug 躲了起来，在 C 中增加 log ，bug 出现的概率会降低。随便加几行 lua 代码看起来就相安无事了，但我知道 bug 就在那里，无法视而不见。

假期第一天，我起了个早床，七点就到了公司。头天陪孩子玩到很晚，他们应该到中午才会起来。我想我有一上午的时间解开心结。

走路去的办公室，路程有半个小时。在珠江边漫步，我整理了思路。通过 git bisect 找到出错的地方效率太低了。调试看起来也很困难。看起来必须依靠读代码这条路了，这也是我最擅长的 debug 方法。但太多代码是同事写的，我的大脑中还没有建立起相关模型，且相关的人都放假了，没有人问，这是最大的障碍。

本来，查找 Segmentation fault 最直接的工具是 Address Sanitizer 。但 mingw 还不支持，用 VC 编译虽然支持，但 VC 编译的版本却不出错。我有一上午的时间，估算了一下，够做一个简易版的 Address Sanitizer 辅助调试。

我们的项目是以 lua 为主框架，C/C++ 只实现了必要的模块。这可以简化内存越界问题的检查手段。我可以假定 lua 以及 ltask 都和这次的 bug 无关。那么问题只会出在 fileserver 引导阶段加载的 C 模块里，而导入 lua 的 C 模块都有清晰的边界。

Lua 管理的内存和 C/C++ 管理的内存也是清晰分开的。我自己实现的 C 模块有完善的内存 hook ，略麻烦的是同事用 C++ 写的几个模块，比较难准确 hook 内存管理函数。

如果我能 hook C/C++ 模块的内存管理，把 CRT 中的内存分配从堆上改为每块直接申请虚拟地址（两头再留下无效页），并在不用后注销，这样就能更快的定位问题了。至少，我更有可能在 gdb 中观察到 bug 。Address Sanitizer 就是用类似的方法做到的，自己针对具体情况做一个并不麻烦。

查了一下 windows 下似乎有一个叫 _CrtSetAllocHooK 的 api ，之前没用过；在 mingw 以及 windows SDK 的 .h 文件中还发现了一个叫 _setheaphook(_HEAPHOOK _NewHook) 的东西，但是 google 了一下，居然完全没有文档说明。

我觉得一上午的时间不太够搞清楚 windows 上这些 CRT 内存 hook 的用法，而我并不想整个五一假期耗在里面，被孩子抱怨。还是换个工作量更少的方法。

既然，Lua 管理的内存和 C/C++ 管理的内存是有清晰边界的，而 C/C++ 这边的内存管理比较难 hook ，不妨从 Lua 下手。Lua VM 允许我们自定义内存管理函数。我用 Windows 的 HeapAlloc 重新定义了一个 lua Alloc ，让每个虚拟机都使用独立的 heap ，并和 C/C++ 模块分开。果然，当我把 Lua VM 申请的内存剥离出去后，崩溃就消失了。

这也佐证了 bug 和 Lua 解释器本身的代码无关。一定是 C/C++ 模块写坏了 Lua VM 所使用的内存。

这时，我突然有了一个有趣的点子：我可以在自定义的 lua Alloc 中正常用 malloc 申请内存，这就能保持和之前的流程完全一致。但这次，我不使用申请到的内存，而是另外从额外的 heap 中再申请一块两倍大的。其中一半留给程序使用，另一半对 malloc 申请的内存做一个快照。

如果程序一切正常，那么 malloc 申请的内存将一直和我额外做的快照完全一致，而若有 bug 改动它的话，我也能准确发现。换句话说，那块 malloc 申请的内存是我提供给 bug 的蜜罐。

实现这个想法并不难，只花了一个多小时。然后，我在 gdb 中捕获了 bug 。捕获点在程序退出时，我的校对代码检查到了对蜜罐不正常的修改。有一小块内存中间的一个字节被加了 1 。

因为相关导入 Lua 的 C++ 模块都不是我实现的，所以一下子我无法联想到会是哪行代码的行为。我在钉钉上给同事留了言，描述了调试思路和我的新发现。倒不是期望他能想起点什么，只是做一次小黄鸭调试法吧。

第二步，我想我应该再接再厉，让 bug 更容易暴露出来，并伺机缩小可能存在 bug 的 C++ 模块的范围。我做了两件事情：

1. 完善了 lua Alloc ，把所有的内存块用双向链表串了起来。但我们有多个虚拟机是并发运行的，需要维护多个链表。这样，我就可以在 ltask 的调度器中检查所有的蜜罐。
2. 修改了同事写的三个相关 C++ 模块的 lua binding 。用宏给所有导入 Lua 的 C 函数加了个壳。这个壳可以 log 下每次 Lua 到 C 的函数调用情况。

在第一件工作中，我顺便加了并发检查，如果同一个 Lua 虚拟机的 lua Alloc 函数被并发执行了，就可以被感知到，这可以说明 ltask 中出现了并发相关的 bug 。和预想的一致，这个并发检查没有被触发。

第二件工作涉及三个 C++ 模块，分别是对 os 文件系统函数的封装（为了实现 vfs ）、对 socket api 的封装、绕过 ltask 做线程间通讯的 api （用于 bootstrap 流程，因为有部分时机早于 ltask）。

我在 ltask 调度器中启用了蜜罐检查，果然提前发现了问题（那个神秘的特定字节加一又出现了）。与之同时，有几个 C++ api 调用在附近发生，它们的嫌疑最大。

我仔细阅读了相关代码。其中之一是 socket select 的实现，实现的略有问题，但没有 bug 。这个等节后再和同事讨论。另一个是线程间通讯的函数，第一眼差点就放过去了，但过了半小时再看却发现了端倪。“如果排除了一切不可能的情况，剩下的，不管多难以置信 ……” 。

流程大约是这样的：当一个 lua vm 想绕过 ltask 给另外一个线程上的 vm 通讯时，同事写了这么一个东西：把需要发送的消息序列化，用 malloc 打包成一个数据块，然后把地址放在一个 C 结构中。随后等在了一个 std::binary_semaphore 上。接受方收取数据块指针后通过这个信号量把发送方唤醒。发送方就可以继续做后续的处理。

这是一个开源的模块，所以我可以展示一下代码。 。

这是 8 个月以前的一次修改，初看没有问题。但我有幸在 skynet 开发中做过类似的事情，所以我意识到 bug 出在这里。这个案例也可以很好的解释为什么 pthread_cond_wait() 需要传一个 mutex 进去。

传递消息的 C 结构放在发送方的 lua vm 的一个 userdata 中，它没有 gc 方法，但依赖 lua 的 gc 回收 userdata 的内存。当发送方收到接收方触发的信号后，逻辑上讲接收方已经用完了这个 C 结构，但实现上并没有。所以发送方如果回收内存够快的话，有可能会先于接收方对这块内存最后的修改。

lua 5.4 增加了分代 gc 后，这种临时申请的 userdata 可能在出了作用域立刻被回收，机缘巧合的话，会比接收方快那么几个指令周期。这样，当接收方最后对信号量的一番改写前，可能在另外一个虚拟机上内存又被分配了出去。

我们观察到的特定字节加一，应该就是信号量的 release 操作（猜测，尚未确认，等节后同事自己推敲修改）。

这也是为何这个 bug 非常容易被 lua gc 干扰，以及只在高并发条件下被触发的缘故了。

终于可以安心陪孩子过节了。

晚上，发出的钉钉消息已读，同事给了个赞 :)

​Read More