我调过的最难调的Bug

每个程序员都有些不畏死亡决战猛兽的英雄事迹。以下这些是我的。

内存冲突

毕业不到半年，拿着刚到手的文凭，我在Lexmark公司的一个嵌入式Linux固件开发团队中负责追踪一个内存冲突的问题。因为内存冲突的原因和问题表象总是相差非常大，所以这类问题很难调。有可能是因为缓存溢出，也有可能是指针未初始化，或是指针被多次free，亦或是某处的DMA错误，但是你所见的却是一堆神秘的问题：挂起、指令未定义、打印错误，以及未处理的内核错误。这些都非常频繁，内存冲突看上去似乎是随机出现又很难重现。

要调试这种问题，第一步是可重现问题。在我们奇迹般地找到这样一个场景之后，故事开始变得好玩起来。

当时，我们发现在运行时因内存冲突而产生的程序崩溃每几百小时就会出现一次。之后有一天有人发现一个特别的打印任务会产生内存冲突从而在几分钟之内就使程序崩溃。我从来不知道为什么这个打印任务会产生这个问题。现在，我们就可以进一步做些什么了。

调试

这个问题可重现之后，我就开始寻找崩溃中出现的模式。最引人注意的是未定义指令和内核错误，它们差不多三分之一的时间就会发生一次。未定义指令的地址是一个合理的内核代码地址，但是CPU读到的这个指令却不是我们期望出现的。这就很简单了，可能是有人不小心写了这些指令。把这些未定义指令的句柄打印出来之后，我可以看到这些错误的指令所在位置的周边内存的状态。

在做了大量失败的将更多的代码排除出崩溃的尝试之后，一个特殊的崩溃渐渐显现。

崩溃之王

这个崩溃解开了所有秘密。当时我们用了一个双核CPU。在这个特殊的崩溃里，首先CPU1在有效的模块地址范围内收到了一个未处理的内核错误，而此时它正在尝试执行模块代码，这段代码可能是一个冲突的页表或是一个无效TLB。而正在处理这个错误时，CPU0在内核地址空间内收到了一个非法的指令陷阱。

以下是从修改后的未定义指令句柄中打印出来的数据（已转为物理地址，括号中是出错地址）

以下是内存域应该显示的数据：

确切地来说，只有一行缓存(中间那32byte)是有冲突的。一个同事指出冲突行中0x49fa30e7这个字是一个魔术cookie，它标记了系统中一个特殊环形缓冲区的入口。入口值的最后一个字永远是一个时间戳，所以0x5439541b是上一个入口的时间戳。我决定去读取这个环形缓冲的内容，但它现在挂在一个不可执行的KGDB提示那了。机器现在跟死了一样。

冷启动攻击

为获取环形缓冲区的数据，我进行了一次冷启动攻击。我为正在使用的主板搞到了一份概要拷贝，然后发现CPU的复位线上连了一块不受欢迎的板子。我把它短路了，重置CPU而不妨碍DRAM的完整性。然后，我把Boot挂载在引导程序上。

在引导程序里，我dump到了问题中环形缓冲区的内容。谢天谢地，这个缓存总是在一个固定的物理地址上被定位到，所以找到它不是问题了。

通过分析错误时间戳周边的环形缓冲区，我们发现了两个老的cache line。这两个cache line里有有效数据，但是在这两个cache line里的时间戳却是环形缓冲区里之前的时间。

导致CPU0上未定义指令的cache line与环形缓冲区里那两个老cache line之一相当契合，但是这并不说明其他可能的地方也是这样。我发现一个决定性的证据。假设，另一个消失的cache line是导致CPU1上未处理内核错误的元凶。

错置的cache line

cache line应该被写入0x0ebd2bc0（环形缓冲区里的cache line），但是事实上却写入了0x0018abc0（冲突的内核码）。这些地址在我们CPU上属于相同的缓存，它们的位[14:5]的值是相同的。不知为何它们有别名。

一个地址的低5位是cache line(32字节cache line)里的索引。后10位，即位[14:5]，表示缓存集。剩下的17位，即位[31:15]，用来表示缓存里当前存的是哪个cache line.

我向我们的CPU供应商提交了一个bug报告，之后他们制定了一个解决方案，并在下一版本CPU里修复了这个bug。

我期望听到更多牛掰的此类故事，也期望我自己可以再攒点这样的。

信息来源：我调过的最难调的Bug