こんにちは、最近ruby-vipsに惚れ込み始めたエンジニアの宮原です🐕

先日、医師専用コミュニティサイト「MedPeer」で使用されているRubyをVersion 2.6.5にアップデートしました🎊

f:id:nyagato_00_miya:20191024163222p:plain

今回は、Rubyアップデートを行った際にハマった箇所について紹介と解説をしてみたいと思います。また、類似の内容で発表もさせていただいておりますので、合わせてご一読いただければと思います。

今回紹介するハマりどころは、ActiveSupport::DurationのバグとSidekiqの安全な再起動についてです。

🐛Durationのバグ

最新のdevelopを取り込み、Rubyアップデートのブランチで作業しているとReceived 'killed' signalというエラーが発生し、CIのRSpecが途中で終了してしまう事象に遭遇しました。

f:id:nyagato_00_miya:20191024182229p:plain — 3並列目でメモリを食いつぶし移行のテストが失敗している

調査を進めると、あるテストで異常な処理時間がかかっていることがわかりました。これによりCircleCIのメモリが枯渇し、残りのテストも軒並み失敗していることが判明しました。メモリを枯渇させるほどの異常な処理の原因も調査を進めていくと、Range#stepにActiveSupport::Durationを渡す箇所でパフォーマンスが著しく低下しており、こちらが原因であることを突き止めました。

どの程度、処理速度に差があるのかを確認するため、以下のコードで検証します。

require 'active_support'
require 'active_support/core_ext'

start = Time.now
(0..300).step(15.seconds).to_a
pp "time: #{Time.now - start}"

処理速度は下記の通りで、Ruby 2.6系を使うと圧倒的に処理速度が悪化していることがわかります。

Ruby 2.5.3	Ruby 2.6.3
time: 2.1e-05	time: 11.550944

こちらの事象が発生する組み合わせは、下記の通りです。

ソフトウェア	バージョン
Ruby	2.6.3, 2.6.4, 2.6.5
Rails	5.2.3
ActiveSupport	5.2.3

github.com ※issueも上がってました。

🔍なぜ計算量が指数関数的に増加してしまったのか

Range#stepとActiveSupport::Durationの挙動が怪しそうなので、検証していきます。下記のようなベンチマークコードを利用して、処理速度を計測していきましょう。

require 'active_support'
require 'active_support/core_ext'
require 'benchmark'

current = 0
step = 15.seconds

loop do
  puts current

  time = Benchmark.realtime do
    current = step.coerce(current).sum
  ene

  p "processing time:#{time}"
end

計測結果は下記の通りです。ご覧の通り、Ruby 2.6系ではステップ数が増加するごとに、著しく処理時間が増加していることがわかります。

f:id:nyagato_00_miya:20191031105425p:plain — Ruby 2.5とRuby 2.6による処理速度の比較

Integer#stepやRange#stepは、Ruby 2.6からEnumerator::ArithmeticSequenceを返すように修正されました。（Ruby 2.5までは、Enumeratorを返してました。）

Ruby 2.6の変更では、Enumerator::ArithmeticSequenceすなわち等差数列が返り値となることを期待しています。しかし、期待するデータ構造が仮に(duration 15)としていたところに、(duration (duration (duration (duration (duration 15))))のようなネストが深いデータ構造で渡ってしまう場合、再帰処理も相まって処理時間が指数関数的に増加していました。

🔧修正するには

Ruby 2.6系とRails 5.2系の組み合わせで、当該事象を回避するにはIntegerとして値を渡せば大丈夫です。

(0..300).step(15.seconds.to_i).to_a

🚦Sidekiq Jobの安全な再起動

RubyやRailsのアップデートを実施する場合は、各サーバーをHard Restartする必要が生じます。しかし、Jobサーバーなどを思い切ってHard Restartしてしまうと、実行中のJobが正しく完了しない場合や2重に実行されてしまうなどの問題が起きる可能性があります。このため、Jobサーバーを安全に再起動する必要が生じました。

🔧安全な再起動手順について

「MedPeer」ではSidekiq Enterpriseを利用していますので、こちらの安全な再起動について解説します。

以下の手順でSidekiqを安全に再起動させていきます。

Jobを新規実行しないようにする
実行中のJobが終わるまで待つ
Sidekiqのプロセスを停止
einhornのプロセスからSidekiqのプロセスを起動

まず、現在実行中のJob数を確認します。

takashi-miyahara@stg-hogehoge-batch-a01:~$ ps -ef | grep sidekiq
medpeer  10921     1  0 10月09 ?      00:00:00 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
medpeer  12864 10921  2 15:38 ?        00:00:18 sidekiq 5.2.7 medpeer [3 of 10 busy] leader
# 　　　　↑こちらがSidekiqのプロセス
takashi+ 13506 13421  0 15:50 pts/0    00:00:00 grep --color=auto sidekiq

どうやら3つのJobが実行中のようですね。

次に、Sidekiqのプロセスへ-TSTP(v5.0.0 未満は USR1)シグナルを送りkillします。

takashi-miyahara@stg-hogehoge-batch-a01:~$sudo kill -TSTP 12864

Sidekiqのプロセスをkill後に、プロセスを確認するとstoppingとなり徐々に実行中のJobが減っていきます。

takashi-miyahara@stg-hogehoge-batch-a01:~$ ps -ef | grep sidekiq
medpeer  10921     1  0 10月09 ?      00:00:00 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
medpeer  12864 10921  2 15:38 ?        00:00:18 sidekiq 5.2.7 medpeer [1 of 10 busy] stopping
takashi+ 13506 13421  0 15:50 pts/0    00:00:00 grep --color=auto sidekiq

その後、すべてのJobが実行済みになることを確認します。

takashi-miyahara@stg-hogehoge-batch-a01:~$ ps -ef | grep sidekiq
medpeer  10921     1  0 10月09 ?      00:00:00 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
medpeer  12864 10921  2 15:38 ?        00:00:18 sidekiq 5.2.7 medpeer [0 of 10 busy] stopping leader
takashi+ 13506 13421  0 15:50 pts/0    00:00:00 grep --color=auto sidekiq

これで、後続のJobが実行されない状態になりました。

次に、TERMシグナルを送りプロセスをkillします。

takashi-miyahara@stg-hogehoge-batch-a01:~$ sudo kill -TERM 12864

しばらくするとeinhornのプロセスが、自動的にSidekiqのプロセスを起動してくれます。これは、einhornのPIDを親プロセスに持つ子プロセス（Sidekiqのプロセス）がkillされると、einhornが新しいプロセスを立ち上げます。

では、新しく起動したプロセスの様子を確認してみましょう。

takashi-miyahara@stg-hogehoge-batch-a01:~$ ps -ef | grep sidekiq
medpeer  10921     1  0 10月09 ?      00:00:00 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
medpeer  13535 10921 92 15:55 ?        00:00:02 /var/www/medpeer/shared/bundle/ruby/2.5.0/bin/sidekiq --config config/sidekiq.yml --environment staging
takashi+ 13537 13421  0 15:55 pts/0    00:00:00 grep --color=auto sidekiq

まだ、Ruby 2.5が使われているようですね。どうやらeinhornの自動再起動では新しいRubyを読み込んでくれないようです。こんな時は、Sidekiqを明示的に再起動してあげましょう。

takashi-miyahara@stg-hogehoge-batch-a01:~$ sudo service sidekiq restart
takashi-miyahara@stg-hogehoge-batch-a01:~$ 
takashi-miyahara@stg-hogehoge-batch-a01:~$ ps -ef | grep sidekiq
medpeer  10921     1  0 10月09 ?      00:00:00 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
medpeer  13535 10921 92 15:55 ?        00:00:02 /var/www/medpeer/shared/bundle/ruby/2.6.0/bin/sidekiq --config config/sidekiq.yml --environment staging
takashi+ 13537 13421  0 15:55 pts/0    00:00:00 grep --color=auto sidekiq
takashi-miyahara@stg-hogehoge-batch-a01:~$ 
takashi-miyahara@stg-hogehoge-batch-a01:~$ sudo service sidekiq status
● sidekiq.service - sidekiq
   Loaded: loaded (/lib/systemd/system/sidekiq.service; enabled; vendor preset: enabled)
   Active: active (running) since 水 2019-10-09 22:00:22 JST; 17h ago
  Process: 12782 ExecReload=/usr/local/rbenv/shims/bundle exec einhornsh --execute upgrade (code=exited, status=0/SUCCESS)
 Main PID: 10921 (bundle)
    Tasks: 22
   Memory: 242.6M
      CPU: 31min 34.652s
   CGroup: /system.slice/sidekiq.service
           ├─10921 einhorn: bundle exec sidekiq --config config/sidekiq.yml --environment staging
           └─13535 sidekiq 5.2.7 medpeer [0 of 10 busy] leader

無事、Ruby 2.6を使って起動していることがわかります。これで、長時間Jobの実行を止めることなくSidekiqを安全に再起動することができました。

当該手順を実行する前に、Jobのスケジュールを確認し再起動できそうな時間帯などを確認しておくと良いでしょう。