Scout APMを利用したHerokuエラー(H12・R14)解析

Herokuでアプリを運用している際に、突然エラーが表示されたという経験はありませんか？このエラーの原因を解析したいが、優秀なDevOpsチームもいるわけでもないので、何をすれば良いか分からないという方々には、Scout APMが役に立ちます。ここでは、Herokuでよく見かける２つのエラーをScoutを使って、今までより早く、効率的にその問題の解析を行い、エラーコードを見つける方法を説明していきます。

Herokuのエラーログについて

まず始めに、Herokuを使用している方に起こりやすい典型的なエラーと、それをデバッグするために、どうScoutを使用していくかを説明していきます。Herokuを頻繁に使用しているユーザーは何度も目にしたことがあるかもしれませんが、Herokuにてエラーが起こった際は、アプリケーションエラーページにおいて、HTTP503のコードと共に、”このサービスはご利用いただけません”と表示されます。

残念ながら、この情報は開発者がデバッグするためには、ほとんど役に立ちません。しかし、Herokuのダッシュボード上のActivityタブにおいて、またはHerokuのCLIアプリケーションを使ってログを深掘りしていくと、その詳細が見えてきます。

$ heroku logs --tail

HerokuはH、R、Lという３つのアルファベットを使い、それぞれHはHTTPに関するエラー、RはRuntimeに関するエラー、LはLoggingシステムに関するエラーを表しています。またHerokuで使用されている、その他のエラー表記はこちらで確認出来ます。例として、下のスクリーンショットに表示されているエラーはH12のエラーということなります。

Scoutでエラーコードから解決策を導き出す

ここまで、ログをチェックし、どのようなタイプのエラーなのかを判別する方法を説明しました。ただ、エラーコードが分かったからというて、Herokuが公開している文書を参考にエラーを修正出来るかと言われたら、そうではありません。このようなエラーコードを見て何のエラーが起こっているかが分かったとしても、なぜ起こってしまったのかということまでは判別できないからです。ここで、それを説明してくれるのがScoutのようなアプリケーションパフォーマンスモニタリング（APM）です。Scout APMは、エラーコードがどこでなぜ起こったのかという情報まで提供してくれます。幸運なことに、Herokuのログシステムは、いつ、何のエラーが発生したかまでは教えてくれますので、典型的な２つのエラーを例として、そのエラーが起こったとき、一体どこでなぜ起こったのかをScout APMを使用して、精査してみましょう。

例１ーH12：リクエスト　タイムアウト

Herokuではリクエストの完了までに３０秒以上かかったとき、このH12エラーが表示されます。このようなエラーは明らかに普通の反応時間の遅れとは異なるため、ScoutのOverviewページにおいて、大きなスパイクとして表示されます。これが調査開始の合図です。

あなたがもしこのようなスパイクをScoutのチャートに表示されいてるのを発見したら、その周りをドラッグしてボックスとして囲います。すると、スパイクの中で起こっていたエンドポイントの簡単なリストが表示されます。その中で、要因と思われるエンドポイントを選択し、そのエンドポイントの中でエラーが発生した時間のトレースを見つけ出します。

この時点で、対象となるトレースを特定することができ、どこで時間やメモリーが消費されてたかがレイヤーごとにブレイクダウンされた情報から分かります。例えば、多くの時間がある一つのモデルに対するデータベースのクエリで消費されているとしたら、そのバックトレースと実際に実行されたクエリを見ることができます。

下記のような例では、多くの時間がコントローラーによって使用されていることがわかります。事実、このプロセスで４０秒以上かかっています。よって、これがH12のエラーコードがHerokuによって表示された原因と判別出来るわけです。

さらに、上記ような例においては、コントローラータイムを細かく分割してくれるAutoInstrumentsを使用することで、より詳細なデバックを可能にしてくれます。以上の作業を経て、コントローラーやバックトレースの中で問題のあるコードがどこに存在するかを確認することが出来ました。ここで、エディットアクション見ると、#edit 22において1 call のsleep (40) のせいで、このアプリが４０秒もプロセスに時間がかかってしまったと判明できるわけです。もちろん、このコードはこの説明をする目的で使用されましたが、Scoutを使うことで、これだけの情報を掴むことが出来ることをお分かりいただけたかと思います。

その他のH12のエラーに関する可能性

• 誰かがアプリを使うとタイムアウトが起こるが、自分で同じエンドポイントにアクセスした際には、全て正常だったという経験は、今まででありましたか？もしかしたら、そのエラーは一日のある一定の時だったり、特定のユーザーのアクセスの時のみに断続的に起こり、あなたの時には全く起こらないエラーの可能性があります。もしかしたら、Scoutのカスタムコンテクストを使うことで解決できるかもしれません。
• トレースエクスプローラーでは、異なる基準のトレースやカスタムコンテクストを使ってトレースを探すことができます。例えば、高い料金プランを選択している顧客のトレースのみを表示するなど。そして、何か問題を見つければ、以上で記したようなステップを試してみてください。

例２ーR14:Memory quota exceeded

Herokuにおいて最も起こりうるエラーがこのR14"Memory quota exceeded"かもしれません。このエラー（同様にR15"Memory quota vastly exceeded")はメモリ使用量を超えてしまった時に起こります。このメモリ使用量はHerokuで、どの料金プランを採用してるかで、決まってきます。

アプリのメモリ使用量を使い切り、R14のエラーが発生すると、そのサーバーはその容量をかき消すためにページを切り替えますが、その後はアプリケーションのパフォーマスは非常に遅くなっていきます。

そして、引き続きメモリを使用し続け、メモリ可能量の２倍のメモリを使用してしまうとR15のエラーが発生し、サーバーは自動的にシャットダウンしてしまいます。

このエラーは頻繁に起こる例ではありますが、APMを使わずしてデバックするのは不可能です。このメモリブロート解析は、競合他社と比較した際に、Scoutが特に優っている部分の一つでもあります。

まず始めに、このようなメモリに関する異常はScoutのOverviewページの線グラフにおいて、スパイクを発見することが出来ます。下のような例では、メモリの使用量が、ある時を境にして急激に上昇したことが確認出来ます。さらに下図の左下にも確認出来る、Memory Bloat Insightsをチェックすると、ArticlesController#index  が表示されており、そこで精査すべき問題を表示しています。

このスパイクが起きた時間のトレースを確認すると、どこのレイヤーで多くのメモリを使用していたかは一目瞭然です。下図の例ではViewのレイヤーになります。さらに、バックトレースから、ペジネーションを行なわず、全レコードを表示していたことが原因だということを特定することができます。

その他のH14のエラーに関する情報

• 一部のユーザーだけがR14のエラーを起こしている場合など、このメモリに関する精査は難しくなります。その時は、カスタムコンテクストを利用すると、問題解決に繋がります。
• メインページのオーバービューページからの問題を探す方法以外にも、ウェブエンドポイントのページで、アロケーションの最大値でフィルターをかけると、メモリの使用量が高いエンドポイントを探すことが出来ます。
• Scoutを利用して、メモリの使用すぎに関するデバッグに興味がある方は、こちらのリンクをご参考ください。

次は？

Herokuを使ってて、上記以外のHerokuエラーを経験したことはありませんか？　そんな時は、お問い合わせお待ちしております。Scout APMチームがデバッグのサポートをさせていただきます。

ここまで、閲読頂きありがとうございます！犬のイラストをクリックしていただきますと、無料でScout関連商品をお届けします！