Scout APMを利用したHerokuエラー解析

BY Matthew Chigira

September 09, 2019

heroku.png

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

Herokuのエラーログについて

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

heroku-error-page.png

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

$ heroku logs --tail

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

heroku-error-cli.png

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

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

例1ーH12:リクエスト タイムアウト

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

spike.png

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

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

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

non-autoinstrument.png

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

autointrument.png

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

例2ーR14:Memory quota exceeded

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

r14.png

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

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

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

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

trace1.png

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

trace2.png

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

次は?

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

doggo-hunter.png

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