Eclipse Memory AnalyzerでRubyアプリケーションのメモリリークを検知する

原文: チャールズ＝オリバー＝ナター

前回の記事「JRubyでメモリを観察するには」の後、何人かの人からEclipse MATのJRubyでの使い方について書いてみたらどうかとの意見を貰いました。これを早速取り上げる事にします。

Eclipse Memory Analyzerは他のEclipseを基盤にしたアプリケーションの例に外れる事なく、起動すると基本ページから個々の作業向けのページへと移動します。

MATは、jhatに較べてもっとインタラクティブにヒープダンプを解析する事が出来ます。MATはjmapのダンプファイルを解析出来ますので、メモリリークを起こしているRailsのアプリケーションからダンプを取ってくる事にしましょう。

このコントローラをアプリケーションに加えました。

class LeakyController < ApplicationController
  class MyData
    def initialize(params)
      @params = params
    end
  end

  LEAKING_ARRAY = {}
  def index
    LEAKING_ARRAY[Time.now] = MyData.new(params)
    render :text => "There are #{LEAKING_ARRAY.size} elements now!"
  end
end

どこかの秀才君が最近使われたリクエストへのパラメータを、時間をキーにカスタムタイプで包んで、定数としてLeakyControllerに後片づけする事なく保存する事にしたようですね。これは一時凌ぎなのかも知れませんし、もしかしたら開発スタッフの中にはオバカサンが紛れ込んでいるのかも知れません。いずれにしてもこれは検知して直す必要があります。

このアプリケーションを動かして/leaky/indexを10000回ほど呼びます。There are 10000 elements now!と出力される筈です。

~ ➔ ab -n 10000 http://localhost:3000/leaky
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 1000 requests
Completed 2000 requests
...

10000のリクエストを処理してしまった後も、アプリケーションのメモリ消費量は、ヒープが一杯になるまで増加の一途を辿ることが解ると思います。（JRubyはJVMで走りますから最大ヒープ量を自動的に設定します。）jmapを使って調査を始めましょう。

~ ➔ jps -l
61976 org/jruby/Main
61999 sun.tools.jps.Jps
61837

~ ➔ jmap -histo 61976 | grep " ruby\." | head -5
 37:         11685         280440  ruby.TZInfo.TimezoneTransitionInfo
 40:         10000         240000  ruby.LeakyController.MyData
133:           970          23280  ruby.Gem.Version
137:           914          21936  ruby.Gem.Requirement
170:           592          14208  ruby.TZInfo.TimezoneOffsetInfo

私達の旧友TimezonTransitionInfoがまた顔を覗かせていますが、これはもうお約束なので気にしない事にします。この、一見して10000個もあるLeakyController::MyDataってなんでしょうか。これはどこから来たのでしょう。これを参照しているオブジェクトなんでしょうか。

ここから、メモリをダンプして、MATを使って解析したり、或いは、VisualVMでやるようにMATでダンプをとって一気に解析に移ったりする事が出来ます。ここではMATに全部やらせることにします。

MATにヒープを読ませる

（注記：ここまで記事を書いてきて、最新のOS X版のJava 6のjmapにはちょっとした欠陥がある事が判明しました。どうやらダンプされないオブジェクトが有るようなのです。結果的にダンプを解析しても表示されないフィールドやオブジェクトがあります。幸いにもSoylatteやOpenJDKのビルドにはこのような問題は存在しないようです。ここでは私がビルドしたOpenJDK 7を使います。

ファイルメニューからAcquire Heap Dumpを選びます。

このダイアログは、前述のjpsコマンドが挙げるのと同じプロセスを表示しますから、解り易いと思います。（JDKのインストールディレクトリを指定しなければならない時は、Configureボタンを押して、jdkhomeフラグをHPROF jmap dump providerに指定して下さい。）

Railsアプリケーション（プロセスIDは61976）を選んで続行です。

MATはプロセスに接続し、ヒープをディスクにダンプして、直ぐにこれを読み込みます。

ダンプの読み込みが終わると、次の選択肢は幾つか有ります。

日が違えば、コンポーネント毎にメモリ消費の多いオブジェクトを探して回ったり、或いは過去の解析結果を見直したりする事にもなるでしょうが、今回はMyDataのリークの解決が最優先なのでLeak Suspects Reportを走らせます。

リーク容疑者ですって?

メモリリークを起こしているかも知れないオブジェクトを探して回る事が出来るなんて便利なツールがあるなんて、冗談ではないんでしょうか。それが本当にあるんですのよ、奥様！

これは、ツールが星の数ほどあるJVMならではの長所だと思います。基本的なツールの数が多すぎて（メモリを調査するものだけで最低1ダースはあるでしょうから）デベロッパはメモリ解析等、特定の目的の為のツールへと移行して行ったのです。私がリーク追跡する時にはMATをよく使います。（jhatに較べてメモリ消費が少ないのでヒープをざっと読むにはとても都合がいいのです。）

さて、MATがヒープを読み込んだところで、メモリリークを起こしていそうなオブジェクトのチャートが表示されます。理論的には、オブジェクトが消費するメモリの量が、ヒープに存在する他のオブジェクトに較べて特別に多いものを探しているのです。今回の場合、MATは、合わせてヒープの半分以上を占めている容疑者を三つ挙げました。

下へスクロールしてこれらを見てみましょう。

容疑者のリストには、Hashが一つ、Moduleが一つ、そして711個のClassオブジェクトが含まれているようですね。JRubyが使う、コアクラスとRailsとそしてRailsが依存するライブラリに含まれるクラスの数は容易に数百に上りますから、Classオブジェクトはここでは無視します。4MBも消費している巨大なModuleがありますが、これについては後述します。

Hashが第一容疑者ですね。これを拡大してみましょう。

新しく表示された情報の一番上のものは「accumulation point」への「最短パス」のリストです。「accumulation point」というのは、リークを起こしていそうなデータが集まっている場所の事です。ただ集まっているだけではないのですが、ここでは一部だけを見ています。

このリストの一番上には、始めに容疑者として挙げられたRubyHashオブジェクトと、それへと連なるオブジェクトの列が表示されています。この場合、Hash自体からConcurrentHashMap、そしてClassオブジェクトのconstantsフィールドへと参照の連鎖を辿って行けます。（ここでは何も隠された要素がないと言う事に注意して下さい。）たったこれだけで何かしらのClassがこのHashオブジェクトを定数として保有している事が解りました。凄いでしょう。

念の為、本当にこのオブジェクトに問題がある事を確認します。もう少し下へとスクロールするとこのHashが集めたオブジェクトのリストが有りますので、これを見てみましょう。

ハッシュテーブルの項目が並んでいますが、もっと詳しく見る事は出来ないものでしょうか。

この項目もクリック出来ますから、どんどんクリックして中身を覗いて行きましょう。項目をクリックすると何が集まったのか解ります。List Objectsメニュー、そしてサブメニューからwith Outgoing Referencesを選びます。

このRubyHashEntryに隠されたMyDataオブジェクトが漸く見えてきました。

これでこのRubyHashが目的のデータである事が確認出来ました。更に、このオブジェクトのキーはTimeオブジェクト（org.jruby.RubyTime オブジェクト）である事も合わせて知ることが出来ました。「最短パス」画面に戻って、このオブジェクトを保有しているConcurrentHashMapについてもう少し詳しく調べてみましょう。このマップのエントリーは定数をキーにしていますから、どのキーがメモリリークを起こしているデータを参照しているかが解る筈です。

（OpenJDK 7を使った事でメモリアドレスが変わっている事に注意して下さい。データの構造に変化は有りません。）

注目のRubyHashを直に参照しているHashEntryオブジェクトから今一度「List Objects」「with Outgoing References」をやります。

ありました！HashEntryのkeyのところに定数「LEAKING_ARRAY」がありました。

例のModuleは？

メモリリークの容疑者に挙げられていたModuleはどうしたんでしょう。ヒープで4MBものスペースを占有していました。これも調べてみましょう。

ああ、どうやらEclipse MATはGemモジュールにメモリリークの容疑を掛けたようですね。何故でしょう。もう一度レポートに戻って、下の方にある「Accumulated Objects by Class table」を見てみましょう。

Gemモジュールが最終的には6000ものGem::Specificationオブジェクト（3.8MBを占有しています）を参照する事が見て取れます。（ところで手元には6000ものgemは決してインストールされてはいません。これはRubyGemsのバグなのかも知れません。もしかしたらJRubyとEclispe MATを使う事でRubyGemsのメモリリーク、又はメモリの浪費を発見したのかも知れませんね。）

Evan Phoenix氏によると私は結果を読み間違っていたようです。Specificationオブジェクトの数は249で、「self」のサイズがおよそ6000バイト、そしてその占めるメモリの量が3.8MBということです。では、MATのもう一つのフィーチャであるCustomized Retained Set計算を使って説明します。

今、保有されているメモリの量がちょっと怪しいですよね。本当に3.8MBものメモリがGem::Specificationsオブジェクトによって保有されているのでしょうか。多すぎると思いますよね。でもGemモジュールの参照を順々に追って行くのは大変面倒です。無駄なデータを省くのに何か良い手段はないものでしょうか。

まず最初にGemモジュール画面に注目します。メモリリークの第二容疑者として挙げられているところの、「Shortest Paths」を拡大します。一番上のRubyModuleがGemモジュールで、ここからCustomized Retained Setを計算します。

出て来るダイアログでは計算の為のオプションを指定する事が出来ます。ここでは、Gem::SpecificationがRubyのクラスとモジュールを参照している部分を除くのが目的ですので、単純にorg.jruby.RubyClassとorg.jruby.RubyModuleを無視することします。

結果は前に見たものと似ていますが、保有されているヒープの量で並べられています。

どういう事でしょうか。全てStringデータのようですね。

JRubyのStringクラスの実装はorg.jruby.RubyStringオブジェクトで行っていますが、それにはorg.jruby.util.ByteListオブジェクトを集め、更にorg.jruby.util.ByteListオブジェクトはJavaのbyte配列を集めたものを用いています。ですから、このリストの上位三つは実質的にはStringと同等であると言えます。これがどこから来ているのかを捜査する最善の方法は、RubyStringについて「List Object」「with Incoming References」をする事でしょう。

やっと、どこからStringがやって来るのかを一望出来る画面が出ました。始めの方にあるものを幾つか調べてみると、それがGemモジュールにある定数のテーブルに有るものだと解ります。これは大した問題ではなさそうですが、RubyStringオブジェクトを保有しているメモリの量の順に並べ替えると、システムの様子が少し違って見えます。

最大のStringオブジェクトを掘り下げてみると、これはGem::Specificationのインスタンス変数に保有されているように見えますね。これはもう少し調べてみる価値がありそうです。

Rubyアプリケーションには押し並べて沢山のStringがあるものです。これだけでは特に変わった事では有りませんが、（バイトそのものに至る迄の）非効率を調査出来るようなツールが有り、またGemモジュールで保有されているデータの一部はクラス序列への参照ではない、「本物」であると知るのは気持ちのいいものです。

（でもこのようなStringの全てがヒープに残っているのがよいかどうかはまだ納得していません。でもこれから先の調査は読者への宿題にします。）

あなたの番です

Eclipse MATは無料で手に入るツールのうち、恐らく最善の物の一つです。オブジェクトの閲覧、メモリリークの検知、GCのルート解析、オブジェクトのクエリ言語の他にも、数多くのフィーチャが本体と第三者からのプラグインには有ります。メモリリークを追いかけていたり、或いは手元の(J)Rubyアプリケーションのメモリ消費を調べてみたいという場合、MATは試してみる価値のあるツールです。（そして、その結果を是非知らせて下さい。）