Feedforce Developer Blog

フィードフォース開発者ブログ

Heroku の Preboot 機能を深掘りした

こんにちは id:masutaka26 です。

この記事は heroku Advent Calendar 2018 の 12 日目の記事です。

qiita.com

昨日は @takuchalle さんの『Heroku で wkhtmltoimage を使う方法』でした。似たツールの webkit2png は使ったことがあります。webkit2png が動作するのは macOS だけですが、wkhtmltoimage は Windows と Linux でも動作するのですね。へぇー。

先月、Heroku の Preboot 機能を調べる機会がありました。Web 上の日本語記事は Preboot が GA になった 2014 年頃の情報が多く、若干情報が古かったため、2018 年時点の最新の情報をまとめます。

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 から確認できます。

f:id:masutaka26:20181210191451p:plain

これを回避できるのが 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 が発生します。

f:id:masutaka26:20181211131034g:plain
Web Dyno 1 台でデプロイした様子

Web Dyno 2 台かつ Preboot 無効でも、基本的に同じです。2 台同時に up → starting → up と変化します。

f:id:masutaka26:20181211131128g:plain
Web Dyno 2 台かつ Preboot 無効でデプロイした様子

Web Dyno 2 台かつ Preboot を有効にすると、期待した通り、1 台ずつ up → starting → up になりませんでした・・・!あれ?

f:id:masutaka26:20181211133556g:plain
Web Dyno 2 台かつ Preboot 有効でデプロイした様子

  • 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 or up) of the new dynos. Old dynos are still running but won’t appear in heroku 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 が FreeHobby では Preboot を有効に出来ません。

Preboot が適用されるのは Web Dyno だけです。自分で定義した worker Dyno 等は対象外です。

まとめ

Heroku の Preboot 機能を深掘りし、有効にする必要性を理解しました。

  • Web Dyno を 2 台以上にしたら Preboot を有効にすると良さそう
  • 前述の「注意事項」には留意したほうが良い

しかし、こんなに長い記事になるとは...。

明日の heroku Advent Calendar 2018 はまたまた id:masutaka26 です。Bitbar の便利な Heroku plugin を紹介してくれるみたいです。お楽しみに。


  1. このような使い捨ての Dyno を One-Off Dyno と呼びます。heroku run で使われる Dyno もそうです。