最近やはりHerokuで運用している無料アプリの Request Timeout がひどくなってきたので、解決策を本家ドキュメントを読んで調べた。以下のページが参考になりそうだ。
https://devcenter.heroku.com/articles/request-timeout
以下完璧じゃない翻訳。しかも抜粋
リクエストタイムアウト
Herokuによって処理されるWebリクエストは たくさんのHeroku routersを通じてあなたのdynos(web プロセス)に直接影響を与えます。これらのリクエストはあなたnアプリをより早くするために動きます。ベストプラクティスはあなたのアプリのレスポンスタイムを500ms以下にすることです。これはあなたのアプリにより多くのリクエストを受けるのを可能にし、訪問者のユーザエクスペリエンスをより良いものにします。場合によってウェブリクエストはあなたのアプリによって、ハングしたり必要以上の時間を取ってしまうこともあり得ます。これが起きたとき、router は30秒以上処理を完了させるのに時間がかかったときには、そのリクエストを終了させます。そのタイムアウトカウントダウンはそのリクエストがrouterを経った時に始まります。そのリクエストはアプリによってdynoの中継で処理されなければなく、レスポンスはタイムアウトを避けるために30秒以内にrouterに返さなければなりません。
タイムアウトが検出されたとき、routerはカスタマイズ可能なエラーページをクライアントに返し、あなたのアプリケーションログにH12エラーを表示します。routerがクライアントにレスポンスを返している間、あなたのアプリケーションは処理がタイムアウトに達したリクエストであるということを知ることはないでしょう。そしてあなたのアプリケーションはそのリクエストを続けて処理することになるでしょう。この状況を避けるためにHerokuはあなたのアプリにタイムアウトを設定し、その値を30m秒以下、例えば10、15秒を設定することをお勧めしています。routingタイムアウトとは違い、これらのチマーはリクエストがあなたのアプリによって処理が始まったときに始まります。
このタイムアウトの値は設定不可能です。もしあなたのサーバが30秒以上かかる処理を必要としている場合、Herokuはその処理をバックグラウンドタスクにするか、定期的にあなたのサーバへ処理が終了しているかping送信することをお勧めします。このパターンはあなたのプロセスをより効率よく使うことができアプリケーションのレスポンス速度を改善することができます。
リクエストタイムアウトのデバッグ
リクエストタイムアウトの一つの原因は無限ループです。そのような問題が発生しないようにローカルでテストするようにしましょう。 その他のWebリクエストで長い期間走る可能性のあるタスクは以下のようなものが挙げられます。
もしそうなら、それらをバックグラウンドジョブに移動し、webリクエストとは非同期に動くようにしましょう。 詳細はWorker dynos, バックグラウンドジョブとキューイングにて。
あなたの使っている外部サービスが利用不可になったり高負荷になったことにより、タイムアウトが発生するパターンがあります。この場合、あなたのWebアプリはその処理をバックグラウンドに移行しなければタイムアウトが発生することでしょう。Web リクエストの間に処理を終わらせなければならない場合、あなたは常に失敗のパターンを考えておく必要があります。ほとんどの言語ではHTTPリクエストのタイムアウトをセットすることができますので、それを検討してください。
効率的なリクエストキューイング
リクエストタイムアウトはdynoの仲のTCPコネクションキューイングが原因で発生することもあります。いくつかのプログラミング言語やフレームワークは一度に一つだけのコネクションの処理しますが、routerにとって、dynoへ１つ以上のリクエストを投げることが可能です。この場合、リクエストはアプリによって処理されることになるその一つをキューに貯められます。これらサブシーケンスのリクエストはそれらが持っている以上のリクエスト時間を必要としてしまう原因となります。あなたはリクエストキューイングされた回数をNew Relic addonにより可視化することができます。この問題は以下のようなテクニックで改善することができます。
- dyno毎により多くのプロセスを走らせる。
- アプリコードの最適化により遅い処理を早くさせる
- より多くのdynoを走らせる
自分がとった対応
無料アプリなのにdynoを増やしてお金を払うって選択肢はあり得なかったので、なんとかコードで改善。そのために、まずはNewRelicアドオンを導入し、どの処理が遅いのかを調べた。すると特定のコードのDB呼び出しが異様に時間がかかっていることがわかった。そこのクエリの調べる対象データ量が4万レコードを超えていた。正直消してもそんなに影響の出ないデータだったので、それを一気に全部消して(わお。。)解決。
