记一次 Ruby 内存泄漏的排查和修复

我首先把怀疑是升级 Rails 导致的问题，于是开始逐步定位到底是哪几个测试如此吃内存。好在测试并不多，逐渐缩小范围查询到了这几个测试文件的某些行。

跟朋友交流的过程中，突然想到了，莫非是 Ruby 2.6.1 的 bug？毕竟 Ruby 从 2.6.0 尝试引入了 JIT，保不齐在某个地方有特殊的触发条件，导致了 Ruby VM 的内存泄漏。要么我们的代码有问题，要么第三方的代码有问题，要么 Ruby 本身的实现有问题。想到这里，整个人精神了不少，开启了满满的 debug 之路。

毕竟第一次见到活的而且可以稳定复现的内存泄漏问题，就跟路上捡到了百元大钞一样兴奋。（当然，我们要拾金不昧，捡到了钱要交给警察蜀黎，那么捡到了 bug 当然是要修复了！）

经过简单的二分法查找，逐渐定位到了几个测试文件：

"zr_attendance/test/services/accounting_service_test.rb"

"zr_time_off/test/models/zr_time_off/request_test.rb:113#valid group days for regular hours"
"zr_time_off/test/models/zr_time_off/request_test.rb:130#valid group days for regular hours when cross weekend"
"zr_time_off/test/models/zr_time_off/request_test.rb:#"
"zr_time_off/test/models/zr_time_off/request_test.rb:#"
"zr_time_off/test/models/zr_time_off/request_test.rb:#"
复制代码

我先把出现内存泄漏的测试用例都集中到某个文件中，然后拷贝一份当前的项目目录，把版本降到 2.5.3，然后跑一遍测试。2.5.3 版本完好，整个跑测试用例过程中，内存稳定在 300MB 以下。

这个时候我们可以确定，内存泄漏问题出现在了 2.5.3 到 2.6.1 的某个版本中。这个时候，我在想，不知道这个版本是 2.5.3 到 2.6.0 还是 2.6.0 到 2.6.1 引入的。 rbenv install -l 给出的 ruby 列表，我们可以看到从 2.5.3 到 2.6.1 之间，经过了好几个版本。所以我们先确定一下是 2.6.0 就引入了还是 2.6.1 才引入，以及是否在最新的 2.7.0-dev 里面就已经解决。于是我可能需要安装四个版本的 ruby。（这纯粹是闲的）

经过几个版本，我发现 ruby 2.7.0-dev 仍然有泄漏问题，瞬间开心了很多，至少证明了这是一个必现的问题，而且是 ruby 2.6.0 引入的。那么理论上，我只要能定位到 在 ruby 2.5.3 版本工作正常的代码在新代码上会出现内存泄漏，那么通过比较两个 ruby 代码版本实现的差异，就能定位到泄漏点。我有种感觉，这个泄漏点应该是来自 ruby 本身。摩拳擦掌准备深挖这个 bug！

通过测试用例，用二分法注释掉代码的笨方法，我逐渐定位到几个测试用例出错的代码行，并根据这个代码行，找到最终在实现里面出现问题的地方。当然对于用惯了 print 大法的人来说，其实就是个体力活。

经过一段苦找，测试用例导致内存泄漏的代码被我精确到了两个点。但是因为这个项目在 2.5.3 上面跑的非常好，而且其实已经经过几个月的线上运行，我们可以认为这个项目在我们找到的对应业务逻辑实现的代码中是没有错误的。而且测试几个 ruby 版本的时候，我们精确的控制了变量，Rails 版本和其他第三方 Gems 版本都一致。

于是我把代码找到，去 console 里面执行，看看 console 里面是否会同样出现内存泄漏问题。很幸运，在找到的两个测试用例调用的代码里面，我在第二个代码里面复现了内存泄漏。

于是，根据代码，我们先从第二个点入手。第二个代码是创建一个请假记录的数据库记录，是一个标准的 Rails 实现，在执行过程中，我发现到这一条 SQL 时候，内存就开始暴涨，所以基本可以确定是这个问题。而另一个代码没有在 console 里面复现，却在跑测试用例的时候出现内存泄漏。考虑了一下，应该是 development 环境对应的数据里面没有跟 worktime 相关的内容，导致无法触发下面的 SQL。

因为两个 Ruby 版本，早前的 2.5.3 是正常的，所以可以排除数据库的问题，而且我们服务器用的是 PostgreSQL，出了 bug 也不一定会被我遇到。另外之所以发现这个问题，是因为 CircleCI 跑测试的时候，超出了 CI 限定的最大内存，所以可以证明这个问题在 Linux 和我自用的 macOS 上都有相同的问题。

一个简单的复现代码如下：

identity = ZrCore::Identity.first;
ZrTimeOff::Request.create!({
  identity: identity,
  category: :in_lieu,
  start_time: '2017-12-1 9:00'.in_time_zone('Beijing').to_time,
  end_time: '2017-12-1 18:00'.in_time_zone('Beijing').to_time,
  created_source: identity,
  status: :passed,
  unit: :halfhour,
  precision: :raw
})
复制代码

继续深究 ZrTimeOff::Request 的实现，发现只要注释掉这行代码，就不会有内存泄漏。

calculate_unit = by_day? ? 'day' : 'hour'
# send("calc_group_days_by_#{calculate_unit}")
复制代码

看样子，我们离罪魁祸首越来越近了，所以我准备使用 binding.pry 在这个地方打断点。从现在看，摆在我们前面的有两条路，一条是 ruby 的 send 方法实现改过，导致行为跟原来的不一致（后来证明想多了），另外一个就是我们通过 send 调用的两个动态方法 calc_group_days_by_day 和 calc_group_days_by_hour 的实现有问题。

通过打断点，我现在不确定 send 方法的实现是否有问题，但是显然，当我调用 calc_group_days_by_hour 的时候，出现了内存泄漏。继续深挖 calc_group_days_by_hour 的实现。

具体细节因为涉及一些业务场景，略过一部分，通过深挖，定位到一个名为 ZrAttendance::DailyQuery 类的一个 overlap_minutes 方法。

发现，只要涉及执行 to_minutes_array 方法的地方，就会出现内存漏液，而这个方法是之前同事实现的。

class Range
  def to_minutes_array
    (self.first.to_i..self.last.to_i).step(1.minute).to_a
  end
end
复制代码

单纯从代码看，没有任何问题。现在似乎可以确定问题了，这个实现在 ruby 2.5.3 和 2.6.0 上表现不一致。

不过，这只是锁定了，冰山上面的部分，至于冰山下面的部分，到底为什么不一致，仍然有很多地方需要深挖。

于是，我们就可以把问题抽象成 (1512090000.. 1512122340).step(1.minute).to_a.count 。

然而经过简单的分析，Range 的长度是 32340，加上 Step 之后仅仅 540 个元素，把 540 个元素转换成数组，无论如何也不至于出现内存泄漏。而按照内存最高占到数 G 大小的情况来分析，显然某个地方出现了严重的问题。

require 'active_support/all'
(1..200).step(8.seconds).to_a
复制代码

如此简单的代码在 2.6.1 就爆掉了，我们有理由相信 Ruby 的实现出现了些许问题。

然而在找 bug 的过程中，某天跟朋友在酒吧里面掏出电脑就是一顿讨论，在讨论的过程中，我们发现其实在一个月以前已经有人给 Rails 项目提出了 Issue github.com/rails/rails… ，并且 @ tenderlove github.com/rails/rails… 给出了简单的修复，但是 @ tenderlove 同时强调，虽然修复了，但是性能在 2.5 和 2.6 比较，2.6 慢了很多。

那么，不影响我们继续深挖原因。通过测试，我们发现，

在 2.5.3 上， (1..200).step(8.seconds).class #=> Enumerator ,

而在 2.6.1 版本上 (1..200).step(8.seconds).class #=> Enumerator::ArithmeticSequence 。

而 Enumerator::ArithmeticSequence 这个是 2.6.0 新加的类，所以问题应该是处在这里了。那么我们该如何界定具体问题出现在哪里呢？我想到之前参加 RubyKaigi 的时候， speakerdeck.com/watson/how-… 给出了一种可以通过 Instruments 来调试找出性能问题的方法。

通过 Call Trees，我们可以看到，绝大多数内存都出现在了 arith_seq_each 调用的 rb_int_plus 里面，那么我们可以断定，这个地方有什么问题导致内存出现暴涨，切一定程度下形成了内存泄漏。经过 printf 大法，我最终发现问题在于 rb_int_plus 里面的 rb_num_coerce_bin(x, y, '+'); 。这个方法最终会落地到： github.com/rails/rails… \

Duration.new(new_value, new_parts)
复制代码

显然，随着 arith_seq_each 的调用，这里逐渐在执行 ActiveSupport::Duration#new ，我发现了一个奇怪的现象，而这个现象极有可能是导致最终内存崩溃的原因：

我们可以看到，这里随着 arith_seq_each 我们发现 ActiveSupport::Duration#+ 的次数会成指数型增长，而随着指数增长的结果就是内存爆掉。为啥 Enumerator 不会崩掉，因为根本就不会跑到这里嘛！而这里的问题也确实如 github.com/rails/rails… 给出的修复，而性能的问题也是出现在： rb_num_coerce_bin(x, y, '+'); 最后落地的实现上。

本来还想研究一下，然后从源头修复掉，后来发现最简单的方案就是：

(1..200).step(8.minute) #=>
(1..200).step(8.minute.to_i)
复制代码

完美！

其实这篇烂尾了，但是思前想后，还是决定发出来，有些有趣的信息说不定可以给大家一些参考。