こんにちは id:masutaka26 です。
この記事は Heroku Advent Calendar 2018 の 12 日目の記事です。
昨日は @takuchalle さんの『Heroku で wkhtmltoimage を使う方法』でした。似たツールの webkit2png は使ったことがあります。webkit2png が動作するのは macOS だけですが、wkhtmltoimage は Windows と Linux でも動作するのですね。へぇー。
先月、Heroku の Preboot 機能を調べる機会がありました。Web 上の日本語記事は Preboot が GA になった 2014 年頃の情報が多く、若干情報が古かったため、2018 年時点の最新の情報をまとめます。
- Preboot 機能とは何か
- どのように有効にするのか
- 使用する Procfile
- デプロイによる heroku ps の変化
- デプロイ時の挙動
- デプロイ時のログ
- 再起動時の挙動
- 再起動時のログ
- 注意事項
- まとめ
Preboot 機能とは何か
Production Check > Dyno redundancy に書いてあるとおり、Heroku では冗長性確保のため、本番環境の Web Dyno は 2 台以上が奨励されています。
Running at least 2 web dynos for any mission-critical app increases the probability that the app will remain available during a catastrophic event. Multiple dynos are also more likely to run on different physical infrastructure (for example, separate AWS Availability Zones), further increasing redundancy.
ただし、それだけだとデプロイや 1 日 1 回の自動再起動で、処理の遅延(H27 - Client Request Interrupted)や H28 - Client Connection Idle が発生することがあります。
以下のグラフは Dyno Restart のタイミングで H27 と H28 Error が発生している様子です。このグラフはダッシュボードの Metrics から確認できます。
これを回避できるのが Preboot 機能です。
どのように有効にするのか
Heroku CLI で有効にできます。
$ heroku features:enable preboot -a YOUR_APP_NAME
有効になりました。簡単ですね。
$ heroku features:info preboot -a YOUR_APP_NAME === preboot Description: Provide seamless web dyno deploys [general] Docs: https://devcenter.heroku.com/articles/preboot Enabled: true
使用する Procfile
今回はこの Procfile を使います。
release: bin/rails db:migrate db:seed # Web app web: bin/rails s -p $PORT -e $RAILS_ENV worker: PROCESS_TYPE=worker bundle exec sidekiq -C config/sidekiq.yml # Ad app ad_worker: PROCESS_TYPE=ad_worker bundle exec sidekiq -C config/sidekiq.yml
web
, worker
, ad_worker
という 3 つの process type を定義しています。今回注目する process type は web
だけです。
1 行目で release
も定義しているため、デプロイ時には One-Off Dyno1 で release 処理をしたあと、生成した Slug が Dyno に展開されていきます。
デプロイによる heroku ps の変化
それでは $ watch 'heroku ps -a YOUR_APP_NAME'
しつつ、デプロイの様子を観察していきましょう。macOS では watch コマンドは $ brew install watch
等でインストール出来ます。
Web Dyno 1 台の場合、release Dyno の実行が終わると、web.1 Dyno のステータスが up → starting → up と変化します。starting 中にリクエストがあると、クライアントは待たされ、前述の H27 や H28 Error が発生します。
Web Dyno 2 台かつ Preboot 無効でも、基本的に同じです。2 台同時に up → starting → up と変化します。
Web Dyno 2 台かつ Preboot を有効にすると、期待した通り、1 台ずつ up → starting → up になりませんでした・・・!あれ?
- Logs will show new dynos starting soon after the slug compile is finished. The output of
heroku ps
will immediately show the state (for example,starting
orup
) of the new dynos. Old dynos are still running but won’t appear inheroku ps
.
Preboot のドキュメントによると、heroku ps では確認できないようです。ただしログでは確認できるそう。
デプロイ時の挙動
- Approximately 3 minutes after the deploy completes (or 2 minutes after your app’s boot timeout limit, which defaults to 1 minute), HTTP requests will start routing to the new dynos and simultaneously stop routing to the old dynos.
遅くともデプロイ完了から約 3 分後、もしくはアプリケーションの起動タイムアウトリミット 2 分(デフォルトは 1 分)後、HTTP リクエストは新 Dyno に Routing されるそうです。
- Shortly after the new dynos are fully live and serving user requests, the old dynos will be shut down. You’ll see them shut down in the logs as usual.
新 Dyno が完全に起動し、ユーザリクエストを処理するとすぐに、旧 Dyno はシャットダウンされるようです。これもログで確認可能とのこと。
では実際にログを見てみましょう。
デプロイ時のログ
git push 後まもなく、Web dyno の状態が up
から starting
に変わりました。
Nov 28 14:58:51 heroku[web] notice Restarting Nov 28 14:58:51 heroku[web] notice State changed from up to starting Nov 28 14:58:51 heroku[web] notice Restarting Nov 28 14:58:51 heroku[web] notice State changed from up to starting
新 Web dyno 2 台で Puma (Web server) がそれぞれ起動を開始しました。
Nov 28 14:59:17 heroku[web] notice Starting process with command `bin/rails s -p 24256 -e production` Nov 28 14:59:19 heroku[web] notice Starting process with command `bin/rails s -p 15417 -e production` Nov 28 14:59:21 app[web] info [heroku-exec] Starting Nov 28 14:59:22 app[web] info [heroku-exec] Starting Nov 28 14:59:31 app[web] info => Booting Puma Nov 28 14:59:31 app[web] info => Rails 5.2.1 application starting in production Nov 28 14:59:31 app[web] info => Run `rails server -h` for more startup options Nov 28 14:59:32 app[web] info => Booting Puma Nov 28 14:59:32 app[web] info => Rails 5.2.1 application starting in production Nov 28 14:59:32 app[web] info => Run `rails server -h` for more startup options
Web dyno の状態が starting
から up
に変わりました。まだ Puma は起動しきっていません。
Nov 28 14:59:33 heroku[web] notice State changed from starting to up Nov 28 14:59:34 heroku[web] notice State changed from starting to up
新 Web dyno 1 台で Puma が起動しきりました。問題はありませんが、手元で起動するよりずいぶん遅い気がします。
Nov 28 15:02:03 app[web] info Puma starting in single mode... Nov 28 15:02:03 app[web] info * Version 3.12.0 (ruby 2.5.3-p105), codename: Llamas in Pajamas Nov 28 15:02:03 app[web] info * Min threads: 11, max threads: 11 Nov 28 15:02:03 app[web] info * Environment: production Nov 28 15:02:03 app[web] info * Listening on tcp://0.0.0.0:24256 Nov 28 15:02:03 app[web] info Use Ctrl-C to stop
旧 Web dyno 1 台で Puma が終了しました。前述の意訳では約 3 分とあるため合っています。
Nov 28 15:02:19 heroku[web] notice Stopping all processes with SIGTERM Nov 28 15:02:19 app[web] info Gracefully stopping, waiting for requests to finish Nov 28 15:02:19 app[web] info === puma shutdown: 2018-11-28 06:02:19 +0000 === Nov 28 15:02:19 app[web] info Goodbye! Nov 28 15:02:19 app[web] info Exiting Nov 28 15:02:19 heroku[web] notice Process exited with status 143
もうひとつの旧 Web dyno 1 台で Puma が終了しました。これも意訳のとおりです。
Nov 28 15:03:25 heroku[web] notice Stopping all processes with SIGTERM Nov 28 15:03:25 app[web] info Gracefully stopping, waiting for requests to finish Nov 28 15:03:25 app[web] info === puma shutdown: 2018-11-28 06:03:25 +0000 === Nov 28 15:03:25 app[web] info Goodbye! Nov 28 15:03:25 app[web] info Exiting Nov 28 15:03:25 heroku[web] notice Process exited with status 143
もうひとつの新 Web dyno 1 台で Puma が起動しきりました。Booting Puma
からずいぶんと時間がかかりました。
Nov 28 15:05:08 app[web] info Puma starting in single mode... Nov 28 15:05:08 app[web] info * Version 3.12.0 (ruby 2.5.3-p105), codename: Llamas in Pajamas Nov 28 15:05:08 app[web] info * Min threads: 11, max threads: 11 Nov 28 15:05:08 app[web] info * Environment: production Nov 28 15:05:08 app[web] info * Listening on tcp://0.0.0.0:15417 Nov 28 15:05:08 app[web] info Use Ctrl-C to stop
Puma の起動に時間がかかるのは謎ですが、Preboot のドキュメントと相違ないと理解しました。
再起動時の挙動
再起動時の挙動も確認します。
Heroku ではアプリケーションの健全性を維持するため、Dyno は 1 日に 1 回、自動的に再起動します。Dyno は差し替えられるため、ローカルファイルシステムの変更はすべて破棄されます。
The new dynos will start receiving requests as soon as it binds to its assigned port. At this point, both the old and new dynos are receiving requests.
新 Dyno は割り当てられたポートにバインドされると、すぐにリクエストを受信し始めます。この時点で、新旧の Dyno がリクエストを受信するそう。
Approximately 4 to 6 minutes after the restart is invoked, the old dynos will be shut down. You’ll see them shut down in the logs as usual.
再起動が行われてから、約 4~6 分後に旧 Dyno がシャットダウンされるようです。これもログで確認可能とのこと。
Preboot が GA になった 2014 年頃は、まだ 1 日 1 回の再起動には対応していないようでした。現在は対応しているようです。
再起動時のログ
結論から書くと、1 台目が再起動し終えてから 2 台目が再起動していました。再起動においても、ドキュメントの通りに Preboot が機能しているようです。
Web dyno 1 台目
Web dyno 1 台の状態が up
から starting
に変わりました。
Nov 30 11:41:22 heroku[web] notice Cycling Nov 30 11:41:22 heroku[web] notice State changed from up to starting
新 Web dyno 1 台で Puma が起動を開始しました。
Nov 30 11:41:42 heroku[web] notice Starting process with command `bin/rails s -p 32434 -e production` Nov 30 11:41:44 app[web] info [heroku-exec] Starting Nov 30 11:41:50 app[web] info => Booting Puma Nov 30 11:41:50 app[web] info => Rails 5.2.1.1 application starting in production Nov 30 11:41:50 app[web] info => Run `rails server -h` for more startup options
Web dyno 1 台の状態が starting
から up
に変わりました。まだ Puma は起動しきっていません。
Nov 30 11:41:51 heroku[web] notice State changed from starting to up
新 Web dyno 1 台で Puma が起動しきりました。相変わらず時間がかかります。
Nov 30 11:45:45 app[web] info Puma starting in single mode... Nov 30 11:45:45 app[web] info * Version 3.12.0 (ruby 2.5.3-p105), codename: Llamas in Pajamas Nov 30 11:45:45 app[web] info * Min threads: 11, max threads: 11 Nov 30 11:45:45 app[web] info * Environment: production Nov 30 11:45:45 app[web] info * Listening on tcp://0.0.0.0:32434 Nov 30 11:45:45 app[web] info Use Ctrl-C to stop
旧 Web dyno 1 台で Puma が終了しました。前述の意訳では約 4~6 分後とありましたが、間を置かずに終了しました。
Nov 30 11:45:55 heroku[web] notice Stopping all processes with SIGTERM Nov 30 11:45:56 app[web] info Gracefully stopping, waiting for requests to finish Nov 30 11:45:56 app[web] info === puma shutdown: 2018-11-30 02:45:55 +0000 === Nov 30 11:45:56 app[web] info Goodbye! Nov 30 11:45:56 app[web] info Exiting Nov 30 11:45:56 heroku[web] notice Process exited with status 143
Web dyno 2 台目
もうひとつの Web dyno 1 台の状態が up
から starting
に変わりました。14 分くらい差があります。最大 216 分のランダムな差があるようなので、記載通りです。
Nov 30 12:00:41 heroku[web] notice Cycling Nov 30 12:00:41 heroku[web] notice State changed from up to starting
新 Web dyno 1 台で Puma が起動を開始しました。
Nov 30 12:00:59 heroku[web] notice Starting process with command `bin/rails s -p 16965 -e production` Nov 30 12:01:01 app[web] info [heroku-exec] Starting Nov 30 12:01:08 app[web] info => Booting Puma Nov 30 12:01:08 app[web] info => Rails 5.2.1.1 application starting in production Nov 30 12:01:08 app[web] info => Run `rails server -h` for more startup options
Web dyno 1 台の状態が starting
から up
に変わりました。まだ Puma は起動しきっていません。
Nov 30 12:01:10 heroku[web] notice State changed from starting to up
新 Web dyno 1 台で Puma が起動しきりました。今回は時間がかかりませんでした。
Nov 30 12:01:15 app[web] info Puma starting in single mode... Nov 30 12:01:15 app[web] info * Version 3.12.0 (ruby 2.5.3-p105), codename: Llamas in Pajamas Nov 30 12:01:15 app[web] info * Min threads: 11, max threads: 11 Nov 30 12:01:15 app[web] info * Environment: production Nov 30 12:01:15 app[web] info * Listening on tcp://0.0.0.0:16965 Nov 30 12:01:15 app[web] info Use Ctrl-C to stop
旧 Web dyno 1 台で Puma が終了しました。今度は時間がかかりました。前述の意訳では約 4~6 分後とあるため合っています。
Nov 30 12:05:14 heroku[web] notice Stopping all processes with SIGTERM Nov 30 12:05:14 app[web] info Gracefully stopping, waiting for requests to finish Nov 30 12:05:14 app[web] info === puma shutdown: 2018-11-30 03:05:14 +0000 === Nov 30 12:05:14 app[web] info Goodbye! Nov 30 12:05:14 app[web] info Exiting Nov 30 12:05:14 heroku[web] notice Process exited with status 143
注意事項
Preboot を有効にしてデプロイすると、無効時よりも時間をかけて Dyno が差し替わります。全ての Dyno に反映されるまで数分かかることもあるようです。この点はチームで把握しておく必要があります。
最大 3 分間、新旧の Dyno が重複するため、Add-on の同時接続数の制限に達する可能性があります。Heroku Postgres の場合は pgbouncer buildpack を使うことが奨励されています。
新旧の Dyno が混在することにより、一度のデプロイで DB schema とアプリケーションコードを変更すると、不具合が発生する可能性があります。Preboot 機能を一旦無効にすることを勧めています。でも、Procfile に release
process type を定義していれば同じなので、個人的には気にならないですね。
Preboot 機能を使うためには、Dyno type が Standard-1X 以上である必要があります。Dyno type が Free
と Hobby
では Preboot を有効に出来ません。
Preboot が適用されるのは Web Dyno だけです。自分で定義した worker
Dyno 等は対象外です。
まとめ
Heroku の Preboot 機能を深掘りし、有効にする必要性を理解しました。
- Web Dyno を 2 台以上にしたら Preboot を有効にすると良さそう
- 前述の「注意事項」には留意したほうが良い
しかし、こんなに長い記事になるとは...。
明日の heroku Advent Calendar 2018 はまたまた id:masutaka26 です。Bitbar の便利な Heroku plugin を紹介してくれるみたいです。お楽しみに。
-
このような使い捨ての Dyno を One-Off Dyno と呼びます。heroku run で使われる Dyno もそうです。↩