記一次 Ruby 內存泄漏的排查和修復

首發 Ruby China 論壇，若是你也在學習 Ruby，不要錯過這個論壇的資料。文章同步發到了公司的公衆號「 春麗說」，歡迎關注。

抱歉從發朋友圈到最終文章，拖了 n 個星期。由於這幾個星期也在處理其餘事情，同時也一直在找最終的泄漏根源，而且指望能夠修復這個問題。固然我失敗了。

又一次撿起來之前的項目，既然要接手，那就準備一下升級到最新的 Rails 5.2.2 和 Ruby 新發的 2.6.1. 然而悲劇出現了，好不容易把依賴處理完了，CI 掛了，並且掛在了一個歷來沒有見到過的錯誤信息上：內存超出了 Circle CI 的限制。

查詢了 Circle CI 的相關文檔 circleci.com/docs/2.0/co… 發現，CircleCI 的內存限制 4GB。潛意識考慮的解決方案是增長內存。但是轉眼一想，不對，由於能夠肯定在我離開這個項目的時候，項目自己是好的。因此我就默默的在個人電腦上跑一下看看，而後我吃驚了。😱

我首先把懷疑是升級 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)
複製代碼

完美！

其實這篇爛尾了，可是思前想後，仍是決定發出來，有些有趣的信息說不定能夠給你們一些參考。