記一次 Ruby 記憶體洩漏的排查和修復

chunlea發表於2019-04-03
記憶體
首發 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)
複製程式碼

完美！

其實這篇爛尾了，但是思前想後，還是決定發出來，有些有趣的資訊說不定可以給大家一些參考。



相關文章