Heroku上のJavaアプリでNewRelicで見る限りメモリはまだ余裕がありそうなのにR14(Memory quota exceeded)がログに出力されるようになり、アプリの応答が極端に悪くなる(というより1台のDynoがほぼ無応答になる)という事象が発生したので、原因を調査しました。
結論から言うとエラーの原因は特定できなかった(いや、まぁメモリ不足であることはわかっている(^^;)んですが、なかなか興味深いこともわかったのでここにまとめておきます。
★ JavaVMのメモリ管理
Javaで使用中のメモリ量を調べる方法としてはRuntimeのメソッドを使用する方法とMemoryMXBeanを使用する方法があります。
http://docs.oracle.com/javase/jp/7/api/java/lang/Runtime.html
http://docs.oracle.com/javase/jp/7/api/java/lang/management/MemoryMXBean.html
前者はHeapメモリのみを対象とし、後者はHeapとNonHeapの両方を対象としています。
なので、Runtimeからとれる値はMemoryMXBeanからも取得できるわけですが、その関係は以下のようになっています。
- Runtime#maxMemory == HeapMemorUsage#getMax
- Runtime#totalMemory == HeapMemoryUsage#getCommitted
- Runtime#freeMemory == HeapMemoryUsage#getCommitted - HeapMemoryUsage#getUsed
ログ等にメモリ使用量を出力する場合、お手軽なのでRuntimeのメソッドの方が使用されることが多いと思いますが、この方法だとNonHeapの容量が含まれていないことに注意する必要があります。
ちなみに今回テストで使用したアプリ(Play1)ではNonHeapは80MB - 100MB位確保されていました。意外と多いです。
★ NewRelicのInstancesページに表示されるメモリ使用量
NewRelic自体もMXBeanを使用して情報収集しているはずなので、ここでの各グラフはMXBeanで取得できる値と対応関係があるはずです。
その対応は多分以下です。
- Physical = HeapMemoryUsage#getCommitted + NonHeapMemoryUsage#getCommitted
- CommittedHeap = HeapMemoryUsage#getCommitted
- UsedHeap = HeapMemoryUsage#getUsed
多分というのは、今回アプリの中からMXBeanの値を定期的にログ出力するようにしてその値をグラフ化するということをやったんですが、そのグラフと自前のグラフでいくらか傾向が異なるからです。
ちなみに自前のグラフはこんな感じ。(1分間隔で出力)
見ての通り、UsedHeapがかなりギザギザしたグラフとなっていますが、これは定期的にgcがかかっているためと推測されます。
しかし、NewRelicのグラフではこのようなギザギザは観測されません。
複数Dynoの平均値だからかとも思ったんですが、1Dynoの場合でもこのようなグラフとはならないので謎です。。。(--
ただ全体的には同じようなグラフとなるので、ベースとしている値は上記であっていると思います。。。
が、先にも書いた通り複数Dynoを使用している場合はNewRelicのグラフは平均値になるのでなので各Dynoがどれだけメモリを使用しているかはNewRelicではわかりません。
あと今回の調査とは直接関係ありませんが、NewRelicのagentのjarファイルはちょいちょいアップデートされているので、たまには見直した方が良いかもしれません。
ほとんどの場合、最初にNewRelicを追加した時にDownloadしたAgentをそのまま使用していると思いますが、2系から3系へのバージョンアップではAgentのオーバーヘッドが減っている、とCHANGELOGに書いてあります。(まぁ実感できるものではありませんが。。。この辺Addonが自動的にやってくれると嬉しんだけれど。)
★ heroku labs:enable log-runtime-metrics
labsの機能、log-runtime-metricsを有効にすると20秒に一回各Dynoのメモリ使用量がログに記録されます。
https://devcenter.heroku.com/articles/log-runtime-metrics
ここで出力される「memory_total」がHerokuが監視しているメモリ使用量で、この値が512MBを越えるとR14が出力されます。
ちなみにR14が出力される間隔も約20秒おきなので、このスイッチで切り替わるのはログ出力の有無だけでメモリ監視自体は常に実行されているのでしょう。
ちなみに記録対象はすべてのDynoなので、heroku run bashとかSchedulerで動いたDynoのメモリ使用量も記録されます。
各Dynoのメモリ使用量が個別にわかるし、オーバーヘッドもほとんどないと思うのでlabsだからと敬遠せずに全部のアプリで有効にした方が良いと思います。
★ Javaのメモリ使用量とDynoのメモリの関係
さて、今回の調査を始めた元々の動機は「NewRelicで見るメモリグラフではそれほどメモリを使用しているようには見えないのにR14警告が出ることがある(気がする)」というものでした。
先のグラフではわざと載せませんでしたが、log-runtime-metricsの値ももちろんログから拾えるのでグラフ化できます。これらを重ねればJavaのメモリ使用量とDynoのメモリの関係がわかるはずです。
その衝撃の計測結果はテストアプリのでのグラフを公開しているので是非直接ご覧ください。(12月16日以降はグラフが見られます。)
なにが衝撃だったかって、Herokuの計測しているmemory_totalがJavaのHeapCommitted(+ NonHeapCommitted)よりも小さいことがあるということです。
そんなことってある？？？
僕の認識ではCommittedというのはJavaによって確保済みのメモリなので、それはプロセスが使用しているメモリとほぼ等しいはずと思っていたんですが、外から見たメモリがそれよりも小さいってどういうこと？？？
そんなはずはねーと思って、アプリ上にpsを叩いた結果を表示するコントローラを付けてみたところ。。。
。。。マジでかーーー。。。ここでもCommittedよりも小さい値が表示されてるよ。。。(--
誰かこの現象を説明してください。m(_ _)m
(12/24 追記)
その後ログに「ps aux」の結果から抜いたメモリ使用量を出力するようにしてグラフに追加したところ、ほぼmemory_rssと重なりました。なので外から見た場合のメモリ使用量はJavaのCommittedメモリよりも大きいことも小さいこともあり、その数字が実際のメモリ使用量(Herokuの監視対象)と考えるのが良いようです。
□□□□
話を戻すとグラフを見るとmemory_totalはJavaから見たメモリ使用量よりも小さい時も大きい時もあります。ただグラフの上がり方を見るとアプリの負荷と相関関係があるのは間違いないです。
アプリ以外にメモリを使っているものというのがイマイチ想像できないんですけど、通信バッファとかもあるんだろうか？psにでてこないプロセスも何かある気がする。(根拠なく言ってます。。。)
これはもうこういうものだと思って飲み込んだ方が良いのかもしれません。。。深入りしても満足のいく結果が得られそうな気がしない。。。(敗北宣言)
ログからDyno毎の正確なメモリ使用量を可視化するツールができただけでもまぁ良しとしますかね。。。(--
★なぜか次回予告
さて、今回作成したグラフツールはまぁまぁ便利です。(ドキュメントとかまったく書いてないけど)
仕組みとしてはPapertraiがS3にアーカイブしたログを引っ張ってきて解析しているので、前日以前のログは見られるわけだけどPapertrailのログがアーカイブされるのはだいたいお昼過ぎ(昔はもっと早かった気がするけど)なので、「今R14出てるよ！」みたいな時には使えない訳です。
そこはやっぱりリアルタイムで見たいのが人情！
。。。かどうかは知りませんが。(^^;
そういやPlatformAPIで直近のログを取得できたな。。。
そういやHerokuってWebSocketサポートしたんだよな。。。
じゃリアルタイムグラフも作れるんじゃね？(^^v
ということで、次回はHerokuとWebSocketの話です。