Ruby言語の各実装において、どんなメモリ消費を解析するツールがあるのかが近頃ちょっとした話題になっています。 それもその筈、Rubyで書かれたアプリケーションの（不具合の調査は言うに及ばず）メモリ消費の具合を詳しく調べるのは容易い事ではありません。 JRubyを使わないのなら、そうです。
JRubyはJVM上で走るので、JVM向けに作られた何十ものツールの恩恵に授かる事が出来ます。 中にはJDKに同梱されているものを含め、メモリの調査、解析、レポートをするものもあります。 ヒープダンプが欲しければ、Hotspot系のJVM（SunまたはOpenJDK）に含まれるjmapやjhatが使えます。 もっと高度なツールが欲しければ、Eclipseを基にしたMemory Analysis Tool、 メモリ及びCPU性能解析ツールであるYourKit、 今ではHotspotに含まれているJavaVMを始め、 数多くの選択肢があります。 こうした数多くのツールのお陰でメモリの調査には事欠きません。
本稿では実際にこのうちの二つのツールをどの様に使いこなすか見ていく事にします。 取り上げたツールは起動中のJVMを観察するグラフィカルなツールであるVisualVMと、 ヒープをダンプして事後解析を可能にするjmapとjhatのタッグチームです。
準備
ここで紹介するツールはJRubyのどのバージョンでも使う事が出来ますが、JRuby 1.6の開発に当たり、 様々な改良を施してあります。 特記すべきは、RubyでのオブジェクトとJavaに於けるオブジェクトが並んで表示されるようにしてある点です。 ここでもう少し解説しましょう。
JRubyではRubyでのコアクラスは全てJavaネーティブのクラスで表されています。RubyのObjectクラスはorg.jruby.RubyObjectで、Stringクラスはorg.jruby.RubyStringで、と言った具合です。通常、コアクラスを拡張する場合、Javaネーティブのクラスをわざわざ書き出したりはしません。替わりに、ユーザによって作り出されるObjectを拡張するRubyObjectがメモリに出現するのです。このやり方には実によい用途があります。即ち、RubyObjectの中を覗いてmetaClassがどのRubyクラスを指しているかを調べるという用途が。
出発点が解るよう、これがどんな風になっているのかを見てみましょう。独自のクラスを生成し、一万個のオブジェクトを生成し、保存して、その後スリープするスクリプトを動かします。
~/projects/jruby ➔ cat foo_heap_example.rb
class Foo
end
ary = []
10000.times { ary << Foo.new }
puts "ready for analysis!"
sleep
~/projects/jruby ➔ jruby foo_heap_example.rb
ready for analysis!
これで実験の準備は出来ました。jmapを使用するに当たってこのスクリプトのプロセスIDが必要です。使い慣れたシェルコマンドを使う事も勿論出来ますが、JDKにはJVMのプロセスIDを集める為のツールが同梱されていますのでこれを使います。jpsというツールです。
~/projects/jruby ➔ jps -l
52862 sun.tools.jps.Jps
52857 org/jruby/Main
48716 com.sun.enterprise.glassfish.bootstrap.ASMain
これから、私は三つのJVMプロセスを走らせている事が判ります。一つはjpsそのもの、もう一つは先程実験の為に走らせたJRuby、そしてもう一つは、ついさっきテスト用にスタートさせたGlassfishサーバです。興味があるのはJRubyですから、プロセスIDは52857です。jmapでこれをどのように扱うか見てみましょう。
~/projects/jruby ➔ jmap
Usage:
jmap [option] <pid>
(to connect to running process)
jmap [option] <executable <core>
(to connect to a core file)
jmap [option] [server_id@]<remote server IP or hostname>
(to connect to remote debug server)
where <option> is one of:
<none> to print same info as Solaris pmap
-heap to print java heap summary
-histo[:live] to print histogram of java object heap; if the "live"
suboption is specified, only count live objects
-permstat to print permanent generation statistics
-finalizerinfo to print information on objects awaiting finalization
-dump:<dump-options> to dump java heap in hprof binary format
dump-options:
live dump only live objects; if not specified,
all objects in the heap are dumped.
format=b binary format
file=<file> dump heap to <file>
Example: jmap -dump:live,format=b,file=heap.bin <pid>
-F force. Use with -dump:<dump-options> <pid> or -histo
to force a heap dump or histogram when <pid> does not
respond. The "live" suboption is not supported
in this mode.
-h | -help to print this help message
-J<flag> to pass <flag> directly to the runtime system
出てきたオプションのうち、一番簡潔なものは-histoです。これでヒープに格納されているオブジェクトをヒストグラムで出力します。これをJRubyのプロセスに使ってみます。
~/projects/jruby ➔ jmap -histo:live 52857
num #instances #bytes class name
----------------------------------------------
1: 22677 3192816 <constMethodKlass>
2: 22677 1816952 <methodKlass>
3: 35089 1492992 <symbolKlass>
4: 2860 1389352 <instanceKlassKlass>
5: 2860 1193536 <constantPoolKlass>
6: 2798 739264 <constantPoolCacheKlass>
7: 5861 465408 [B
8: 5399 298120 [C
9: 3042 292032 java.lang.Class
10: 4037 261712 [S
11: 10002 240048 org.jruby.RubyObject
12: 3994 179928 [[I
13: 5474 131376 java.lang.String
14: 1661 95912 [I
...
出力結果はJVMのシステムに存在している文字通り全てのオブジェクト（JRubyに全く関係の無いものまで）を表示します。この結果の価値は明らかでしょう。自分で書いたコードのメモリ消費だけではなく、同じプロセス内に存在している全てのライブラリ、全てのコードを、バイト配列（上記の[B）やJavaのString（上記の"java.lang.String"）に至るまで全て調べる事が出来ます。特別JRubyに関わる事は何もやっていません。
本題に戻りましょう。 僕らの書いたFooクラスは一体どこへ行ったのでしょう。
答えは実は目の前にあります。10002個あるorg.jruby.RubyObjectのうち、10000個はFooオブジェクトに他なりません。残り二つはRubyランタイムが作った何かでしょうが、この出力結果からは残念ながら区別出来ません。JRuby1.6ではこれが改善されます。
今開発中のブランチではユーザによって作り出されるRubyのクラスにJavaのクラスをあてがう為のオプションを使う事が出来ます。これを使うともっと使い勝手のよいプロファイル結果を得るなどの利点があります。このオプションを使ってみましょう。（1.6リリースまでには、これがデフォルトになるか、或いはこのように長いオプションを使わずに済むようになると思います。）
~/projects/jruby ➔ jruby -J-Djruby.reify.classes=true foo_heap_example.rb
ready for analysis!
このプロセスにjmapを使うと、さっきのよりも面白い結果が得られます。
num #instances #bytes class name
----------------------------------------------
1: 22677 3192816 <constMethodKlass>
2: 22677 1816952 <methodKlass>
3: 35089 1492992 <symbolKlass>
4: 2860 1389352 <instanceKlassKlass>
5: 2860 1193536 <constantPoolKlass>
6: 2798 739264 <constantPoolCacheKlass>
7: 5863 465456 [B
8: 5401 298208 [C
9: 3042 292032 java.lang.Class
10: 4037 261712 [S
11: 10000 240000 ruby.Foo
12: 3994 179928 [[I
13: 5476 131424 java.lang.String
14: 1661 95912 [I
Fooクラスがあるのが一目瞭然ですね。"reify classes"オプションにより、Rubyクラスと同じ名前のJVMクラスが、ruby.という接頭辞付きで生成されました。まだまだ小手調べですが、JVMのツールの本当の力を垣間見る事が出来るようになります。簡素なRailsアプリケーションを走らせて、結果を見てみましょう。
~/projects/jruby ➔ jmap -histo:live 52926 | grep " ruby."
29: 11685 280440 ruby.TZInfo.TimezoneTransitionInfo
97: 970 23280 ruby.Gem.Version
98: 914 21936 ruby.Gem.Requirement
122: 592 14208 ruby.TZInfo.TimezoneOffsetInfo
138: 382 9168 ruby.Gem.Dependency
159: 265 6360 ruby.Gem.Specification
201: 142 3408 ruby.ActiveSupport.TimeZone
205: 118 2832 ruby.TZInfo.DataTimezoneInfo
206: 118 2832 ruby.TZInfo.DataTimezone
273: 41 984 ruby.Gem.Platform
383: 14 336 ruby.Mime.Type
403: 13 312 ruby.Set
467: 8 192 ruby.ActionController.MiddlewareStack.Middleware
476: 8 192 ruby.ActionView.Template
487: 7 168 ruby.ActionController.Routing.DividerSegment
508: 6 144 ruby.TZInfo.LinkedTimezoneInfo
523: 6 144 ruby.TZInfo.LinkedTimezone
810: 4 96 ruby.ActionController.Routing.DynamicSegment
2291: 2 48 ruby.ActionController.Routing.Route
2292: 2 48 ruby.I18n.Config
2293: 2 48 ruby.ActiveSupport.Deprecation.DeprecatedConstantProxy
2298: 2 48 ruby.ActionController.Routing.ControllerSegment
...
ruby.を含む結果だけに絞りました。実に素晴らしい結果です。不可思議な事に970個ものGem::Versionオブジェクトが少なくとも23280バイトを消費しているのが解ります。更に残念な事に11685個に及ぶTZInfo::TimezoneTransitionInfoのインスタンスが280440バイトを消費している事も解ります。
さあ、使えるデータが出揃ってきたところでjmapとjhatについてもう少し詳しく見て行きましょう。
jmapとjhat
ご推察の通り、JRubyを開発するときに私はプロファイラーを多いに使います。かれこれ10個ほどのツールを使った事があると思いますが、最初に手が伸びるのは決まってjmapとjhatのコンビです。
jmapの一番簡単な使い方は既に見ました。次はオフラインのヒープダンプを見てみます。
~/projects/jruby ➔ jmap -dump:live,format=b,file=heap.bin 52926
Dumping heap to /Users/headius/projects/jruby/heap.bin ...
Heap dump file created
こんなに簡単に使えます。バイナリのダンプのファイル、heap.binは幾つかのツールで中身をみる事が出来ます。当然、jhatが使えますし、VisualVMやEclipse Memory Analysis Tool等も使えます。何かの標準に則ったフォーマットではありませんが、長い間そのフォーマットは変わっていません。jhatのオプションを見てみましょう。
~/projects/jruby ➔ jhat
ERROR: No arguments supplied
Usage: jhat [-stack <bool>] [-refs <bool>] [-port <port>] [-baseline <file>] [-debug <int>] [-version] [-h|-help] <file>
-J<flag> Pass <flag> directly to the runtime system. For
example, -J-mx512m to use a maximum heap size of 512MB
-stack false: Turn off tracking object allocation call stack.
-refs false: Turn off tracking of references to objects
-port <port>: Set the port for the HTTP server. Defaults to 7000
-exclude <file>: Specify a file that lists data members that should
be excluded from the reachableFrom query.
-baseline <file>: Specify a baseline object dump. Objects in
both heap dumps with the same ID and same class will
be marked as not being "new".
-debug <int>: Set debug level.
0: No debug output
1: Debug hprof file parsing
2: Debug hprof file parsing, no server
-version Report version number
-h|-help Print this help and exit
<file> The file to read
For a dump file that contains multiple heap dumps,
you may specify which dump in the file
by appending "#<number>" to the file name, i.e. "foo.hprof#3".
All boolean options default to "true"
基本的にjhatにヒープダンプを投げてやれば、jhatは仕事を始めます。解析するヒープが大きいと-Jを使ってjhatを走らせるJVMにヒープ用のメモリを多くやらないといけない場合も稀にあります。Railsのアプリケーションを解析しますので、ちょっと多めにヒープメモリを与える事にします。
~/projects/jruby ➔ jhat -J-Xmx200M heap.bin
Reading from heap.bin...
Dump file created Fri Jul 09 02:07:46 CDT 2010
Snapshot read, resolving...
Resolving 604115 objects...
[much verbose logging elided for brevity]
Chasing references, expect 120 dots........................................................................................................................
Eliminating duplicate references........................................................................................................................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.
「サーバの準備完了」と出ました。何ですかそれは！Javaでは何でもかんでもサーバでやるんですか？
まあ、ここでは実際使い勝手が良いので見逃す事にします。jhatはポート7000でウェブサーバを立ち上げました。これでバイナリの中身をマウスを使って調べる事が出来ます。どんなものでしょう。
これが最初のページです。JVMクラスがリストされています。下へスクロールすると一般的な機能が幾つかあります。
ヒープのヒストグラムを選びます。
沢山のオブジェクトがメモリを消費しているのが見て取れます。オブジェクトにはJVM固有のものもあれば、JRubyの実装の為の物も、Rubyのクラスからの物もあります。ここでもTZInfo::TimezonTransitionInfoがあるのが解りますね。クリックしてみましょう。
クラスに関する情報だけで、これと言って余り面白いものはありませんね。しかし、この画面の一番下からTimezoneTransitionInfoのインスタンスを見る事が出来るようです。やってみましょう。
段々面白くなってきました。このようなものが沢山有るのが解ります。もうちょっと調べるのに一番始めのインスタンスをクリックします。
これは凄い。
TimezonTransitionInfoにあてがわれたJVMクラスには三つのフィールドが有るのですね。一つはmetaClassで、Rubyのクラスを指します。もう一つはvarTableで、インスタンス変数や内部で使われている変数を格納している配列です。最後は、freezeされているか、taintされているか等、プログラムの実行時に使う様々なフラグを示すフィールドです。これらのフィールドを見ても良いですが、本稿では飛ばします。
更に下へ行くと、もっと凄いリンクが有ります。一つはこのオブジェクトへのリファレンスのリスト。これを見ると、もう使われていない筈なのに、どうしてTimezoneTransitionInfoがGCされずにメモリに残っているのかが解ると思います。jhatでこのオブジェクトを生かす事になっているリファレンスの連鎖を、スレッドやJVMのオブジェクトにまで遡って見る事も出来ます。また、この連鎖を逆の方に辿って行く事も出来ます。
これはjmapとjhatの機能のほんの一部に過ぎません。こんなに簡単で良いのかな、と思えるくらいに使い勝手がいいです。でも、実行中のアプリケーションを観察するにはどうすればいいでしょうか。ヒープをダンプしてオフラインで解析することで得られる情報は多いですが、オブジェクトが生成されて、そしてGCされて行く様を見たい場合も時としてあります。VisualVMを使います。
VisualVM
VisualVmはNetBeansのプロファイリングのツールとして生まれました。往時のJVMについての大きな不満の一つは、同梱されいたツールがJVMを開発するエンジニアだけを対象にデザインされていた物だったという事があります。Sunには、IDEと関連するモジュールを作るという先見の明があって、これが、誰にでも使えるようなプロファイラーが自然と生まれました。これがVisualVMの起源です。
Java 6をインストールしてあるコンピュータ殆どでjvisualvmコマンドとして実行出来ます。やってみましょう。
VisualVMを立ち上げると、現在実行中のJVMがjpsコマンドの場合と同じように表示されます。他のコンピュータで実行中のJVMに接続したり、ヒープダンプやコアダンプを解析したり、過去に見たメモリやCPUプロファイリングのスナップショットを見る事も出来ます。今回は、実行中のRailsアプリケーションを見てみましょう。
VisualVMが実行中のプロセスに接続して、プロセスやJVMについての基本的な情報を出しました。ヒープの使用状況に興味が有りますのでMonitorのタブをクリックします。
色々と有益な情報がもう入ってきました。この画面ではCPUの使用状況、ヒープの使用状況、JVMで使われているクラスの数と動きの有ったスレッドの数が表示されています。弄り始める前に一旦掃除しようと思えば、ガーベージコレクターを作動させる事も出来ます。最大の利点はjmap/jhatの二つのツールを使ってやっていた事がHeap Dumpボタンを押すだけで一気に出来る事でしょう。魅惑的でしょう？
初期状態ではヒープの総合的な情報が見えます。全体のサイズ、クラスの数、ガーベージコレクターのルートなどです。TimezoneTransitionInfoを探してClassesをクリックします。
ちょっと下の方に有りました。予想通りの数だけ在りますからダブルクリックしてもっとよく見てみましょう。
jhatで既に見たのと同じ情報ですが、ここではもっと見やすくなっていますね。どれをクリックしても何か起きます。ヒープのあちこちを見て回ったり、かなりの手作業を要するような解析も簡単に出来ます。別なツールも見てみましょう。Retained Size計算機です。
ここで見ているJVMのツールにとっては全てのオブジェクトは平等ですから、報告されている、ヒープでのRubyオブジェクトの大きさというのは全てではありません。前述の変数を格納しているテーブル、オブジェクトのインスタンス変数、そしてオブジェクトが参照しているオブジェクトなども考慮に入れなければなりません。別なオブジェクト、Gem::Versionでこれを見てみる事にします。
スクロールしてruby.Gem.Versionクラスを探すのは面倒ですから検索しましょう。OQL ConsoleではSQLに似たクエリでヒープの中から条件に見合ったオブジェクトを探し出す事が出来ます。ruby.Gem.Versionのインスタンス全てを探します。
クエリが実行されてGem::Versionオブジェクト全てが出てきました。これを掘り下げてどれくらいのメモリをVersionオブジェクトそれぞれがヒープにキープさせているのかを見てみましょう。
Compute Retained Sizesボタンを押すと、Instancesペーンがこのダイアログで警告を出します。これくらいではやられません。Yesをクリックします。
ちょっと休憩…
結果が出ました。Versionオブジェクトはそれぞれ125バイトから190バイト、全部で19400バイトを消費しているようです。その殆どは変数テーブルに当てられているようです。何が入っているのでしょう。
なるほど、文字列と配列のようです。ヒープに色々と探りを入れ続ける事も、JRubyやJVMのクラスの中身を見たりして、アプリケーションの本当の姿を見る事が出来ます。凄い力を手に入れました。
あなたの番です
勿論これは氷山の一角です。例えば、Eclipse Memory Analysis Toolにはメモリリークを探知する機能があります。VisualVMとNetBeansにはアロケーショントレーシングという、アプリケーションコードのどこでオブジェクトが生成されているのかを見せる機能もあります。GCの動向を見せるツールも数多く有り、中には稼働中のヒープを弄ってオブジェクトを操作出来るものすらあります。あったらいいな、と思うような機能は何かしらのツールに備わっている、と言えるくらいです。JRubyを使えばそのようなツール全てを何の手を加える事もなく使えるのです。
ここで述べたツールは全てJRuby 1.5.1で使えますが、Rubyクラスに上手に対応するJVMクラスはありません。それにはソースコードからビルドするか、1.6.0.devバージョンをダウンロードするか、或いは1.6.0のリリースを待つかする必要があります。これらを含め、どんなツールを使っているか、是非報せて下さい。このブログでも取り上げたいと思います。
近いうちに、他のツールと、CPUプロファイリングについても取り上げます。それまでは、JRubyを使えばこのような素晴らしいツールが使えるのだと言う事を覚えておいて下さい。
0 件のコメント:
コメントを投稿