排查一例 C++ 和 Lua 交互的诡异 bug

2018-06-11 本文已影响3人豌豆很烦

最近我负责的一个线上 Lua 服务偶尔会 crash，陆陆续续查了好几个星期，上周终于解决了，记录一下排查的过程和思路，这次排查中第一次按照之前看的一本故障排查的技巧进行分析，感觉很有用。

服务架构

首先介绍下线上服务的架构，我们线上是一个推荐系统，推荐系统的重排模块使用 Lua 开发，使用 Lua 的原因，主要是 Lua 作为脚本语言，性能比较好，容易和 C++结合，也适合应付需求的迭代（我们系统 80% 的临时需求，都在重排模块实现，需要快速迭代）。

重排模块的网络框架用 C++ 实现，我们对 C++ 和 Lua 的交互接口进行了一层封装；Lua 代码用来实现重排的业务逻辑。Lua 和 C++ 通过一些接口来互相调用，例如

Lua 需要调用 C++的接口获取正排信息（后文把这个接口称作GetDocInfo，正排信息写作 DocInfo）。
Lua 的输入包括用户画像信息（后文称作 Profile）和推荐结果（后文称作 Meta）的信息。

Profile 和 Meta 都使用 Protobuf 定义，框架会通过 Protobuf 的反射，把 Protobuf 结构转换成 Lua 中的 table，而 DocInfo 则放在共享内存中，没有使用 Protobuf 定义。DocInfo 信息需要经常更新，更新 DocInfo 的操作不是一个增量更新，而是全量更新 DocInfo，因此更新操作以后，同一个 DocInfo 的地址会发生变化，我们会使用 double buffer 的方法，来更新 DocInfo，减少更新操作对请求的影响。

在迭代过程中，GetDocInfo 是做了优化的。最初 GetDocInfo 需要实现一个转换函数，把 DocInfo 整体翻译成 Lua table，但分析发现一个 DocInfo 中的字段并不都会在 Lua 中使用，因此这个整体的翻译操作，实际上做了很多无用功。因此，我们使用了 Lua 的 userdata 来进行优化，原理就是 Lua 调用 GetDocInfo 时，直接返回一个 userdata 的结构，userdata 实际的内容，是一个指向 DocInfo 实际内存位置的指针，当真的需要使用 DocInfo 中的某个字段时，再通过 userdata 的index方法，解析对应的字段，返回给 Lua，这个优化可以把整个重排的耗时降低10%左右，单接口的耗时减少 50% 以上，这当然不好直接比较，因为修改后的方法，只是获取一个指针，相当于是在使用字段时分摊了翻译字段的时间。

此外，这个过程还可以实现一些缓存，例如：

在 C++ 中，可以有一个缓存，放在从共享内存中获取 DocInfo 之前，这个缓存是进程级的，需要在 DocInfo 更新时做清除操作。
在 Lua 中，实现一个全局的缓存，缓存 userdata 信息，这个缓存是脚本级别的，只要脚本不更新（脚本会在更新业务逻辑是更新）缓存就一直存在，这个缓存也需要在 DocInfo 更新时做清除操作。
在 Lua 中，还可以实现一个请求级别的缓存，缓存的是 userdata 信息，这个缓存会在请求结束后清空，每个请求只有几十毫秒，远小于 DocInfo 更新的间隔，加上 DocInfo double buffer 的保护，这里不需要考虑请求过程中，DocInfo 更新的问题。

分析 crash

crash 就发生在使用 DocInfo 的某个字段时，core 文件能够提供的信息很少，一是因为堆栈中的 DocInfo 地址已经不可读，无法从 DocInfo 中获取导致 crash 的 id；二是服务采用了 gcc -O2 的编译参数，一些堆栈信息被优化了，堆栈中没有发现有用信息；三是因为调用过程经过了 Lua，gdb 无法直接打印 Lua 中的堆栈信息，不知道 Lua 代码执行到了哪一行，也导致了分析没有头绪。

调试信息一

由于线索比较少，首先就是希望能找到导致 crash 的 id，通过逐层打印堆栈信息，我发现可以在 index 对应的处理函数中增加一个临时变量，记录 DocInfo 的 id，这样没准下次 crash 时，就可以知道导致 crash 的 id了。

方案一

再次 crash 时，我检查乐这个增加的 id 信息，发现已经不是一个合法的 id，此时我推测是不是调用 GetDocInfo 获取的 Docinfo 就是错的，如果是这样，虽然还没有找到问题的原因，但是可以增加代码，处理这种异常，例如：我可以在 GetDocInfo 内部获取到 DocInfo 指针时，立刻将输入的 id 和 DocInfo 的 id 做一次对比，如果不一致，就认为 DocInfo 已经失效，返回错误。

调试信息二

这次改动并没有解决问题，进程还是会 crash，这说明在获取 Docinfo 时，这个 id 还是正确的，是在之后的某个时间点， DocInfo 的地址才失效。此时暂时没有思路，希望能有更多的调试信息，我想看到 Lua 的调用栈，看看能不能有线索，google 发现 OpenResty 的项目中，有个开源的工具可以通过 lua_State 指针在 gdb 中展示 Lua 的堆栈信息，只是这个工具和 OpenResty 有些依赖，还需要自己小小修改，尝试了几次后，我看到了core 文件中的 Lua 堆栈，同时 Lua 各个栈中的变量也都可以查看，此时可以参考的信息变多了，但是依然没有发现线索。

调试信息三

于是我又回过头，思考什么情况下 DocInfo 地址会失效。就算是地址失效也分两种情况：

userdata 中的 DocInfo 地址被修改了，就是说调用 GetDocInfo 时，得到的就是一个正确的地址，但是后来因为一些操作，把这个地址给修改了，导致地址失效。
DocInfo 的地址没变，但这块地址的数据被修改了，这有可能是 DocInfo 更新时导致的。
我怀疑索引更新有问题，例如double buffer 的代码有 bug，导致我应该读 A 份索引时，读到了 B 份索引，导致地址错误。

这些猜测都要想办法验证。首先就是修改代码，在 C++ 中增加一个 debug 信息，记录当前请求中，所有调用 GetDocInfo 的 id 和对应返回的 DocInfo 地址。我希望不光是能在 core 文件的堆栈中看到这个信息，还要能看到 crash 进程之前请求中的 debug 信息；另外，通过/proc/id/smap 可以看到共享内存中两份索引使用的内存地址范围，这样就可以通过 DocInfo 的地址，知道用的是哪份索引文件。

第 N 次分析 crash

再次遇到 crash，此时因为有几个思路都要验证，为了不走回头了，我特意开了一个文档，记录自己这次分析中的一些信息，例如

导致 crash 的 id。
出错请求的标识信息（可以找到用户的画像）。
出错的时间点。
c 堆栈中看到的 DocInfo 地址。
通过 smap 看到的两份索引文件的地址范围。
两份索引文件的更新时间。
对照出错时间点，同机器，其他进程请求中，获取相同 id 时，取到的 DocInfo 地址。
调试信息三中添加的 DocInfo 和 id 的对应关系。
crash 的请求中 Lua 已经处理过哪些 id。

然后对这些信息进行分析

发现同时间点，同机器，其他进程获取到的相同 id 的 DocInfo 和 crash 进程不一样。说明 crash 进程 GetDocInfo 函数返回了一个错误地址。
分析 crash 进程之前一段时间，crash id 的 DocInfo 地址，发现 crash 时的地址，在之前请求是出现过，说明 crash 时，是使用了一个过期的地址。
发现 crash 的请求中，有一些 Lua 处理过的 id，在调试信息三中，没有找到对应的 DocInfo 地址，说明 Lua 在处理这些 id 时，没有调用 GetDocInfo。

最后的分析

此时已经有些思路了，感觉 crash 的请求，是使用了缓存中的 DocInfo 地址。检查代码，发现上面提到过的第三种缓存可能会有些问题。我们服务的 Lua 调用链如下所示：

-- main.lua
function main()
    local tuner = require "tuner.lua"
    tuner.doTuner()
end

-- tuner.lua
local context = {
    local cache = {}
}

local function GetDoc(id) 
      if context.cache[id] ~= nil then
           return context.cache[id]
      end

      local DocInfo = GetDocInfo(id)
      if DocInfo ~= nil then
          context.cache[id] = DocInfo
     end
     return DocInfo
end

local _M = {}
function _M.doTuner()
     GetDoc(id)
     -- other logic
     context.cache = {}
     return metas
end

在main.lua中，每个请求都会调用main()，虽然每个请求都会调用 require，但是 Lua 会对 require 的模块做一个缓存，即 tuner 对象实际是同一个。而在tuner.lua中，context 作为一个局部变量，只会在 main.lua 调用require "tuner.lua"时执行一次，因此需要在doTuner的最后，调用context.cache = {}清除缓存。
如果代码顺利执行，清除缓存的逻辑肯定会执行，但如果doTuner的执行过程中发生了异常，导致了 Lua Crash（Lua Crash 不会导致进程 crash），那么此时context.cache还会生效吗？经过测试，发现 context.cache 还是会生效。而这次进程 crash 就是这个原因导致的，通过搜索 crash 进程的日志，发现 crash 之前，确实发生了一次 Lua Crash，而且这个请求也通过GetDocInfo获取了导致 crash 的DocInfo，修复这个 bug 的方法很简单，就是把context.cache={}这条语句移动到doTuner的第一行即可。

修改上线后，观察一周，crash 未复现，bug 解决。

参考文章：
用 gdb 分析 coredump 的一些技巧