こんにちは、最近ruby-vipsに惚れ込み始めたエンジニアの宮原です🐕
先日、医師専用コミュニティサイト「MedPeer」で使用されているRubyをVersion 2.6.5にアップデートしました🎊
今回は、Rubyアップデートを行った際にハマった箇所について紹介と解説をしてみたいと思います。 また、類似の内容で発表もさせていただいておりますので、合わせてご一読いただければと思います。
今回紹介するハマりどころは、ActiveSupport::DurationのバグとSidekiqの安全な再起動についてです。
🐛Durationのバグ
最新のdevelopを取り込み、Rubyアップデートのブランチで作業しているとReceived 'killed' signalというエラーが発生し、CIのRSpecが途中で終了してしまう事象に遭遇しました。
調査を進めると、あるテストで異常な処理時間がかかっていることがわかりました。これにより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系ではステップ数が増加するごとに、著しく処理時間が増加していることがわかります。
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のスケジュールを確認し再起動できそうな時間帯などを確認しておくと良いでしょう。
これから
前々回のRubyアップデートから約9ヶ月を経て、最新のRubyで「MedPeer」が動作するようになりました。 「MedPeer」の開発メンバーも増えてきましたので、もう少し早い周期でRubyのアップデートができそうですね。
今後も、RubyやRailsのアップデートに関する内容を発信していければと思います！
(☝︎ ՞ਊ ՞)☝︎是非読者になってください
メドピアでは一緒に働く仲間を募集しています。 ご応募をお待ちしております！
■募集ポジションはこちら
https://medpeer.co.jp/recruit/entry/
■開発環境はこちら
