インタプリタ開発者によるRubyの挙動解析への道

Ruby インタプリタを開発している笹田です。今年のクリスマスにリリース予定の Ruby 2.6、楽しみですね（無事、出るといいな）。

この記事では、私がRubyの挙動を調べるために頑張った記録を書いておきます。 基本的に、単純作業の積み重ねなので、難しい内容はありません。お気楽にお読みいただければ幸いです。

大雑把にまとめると、こんな内容が書いてあります。

  • デバッグカウンタの導入によるRubyの詳細な挙動調査の紹介
    • （私には）簡単な話で、Rubyをいろいろいじって、Rubyの細かい挙動、しかもほとんどの人が気にしない挙動を調べられるようにした話です。
    • 多くの人が興味ないだろう、Rubyに仕込まれている統計情報をとる仕組みを紹介します。
  • クックパッドアプリを手元で調査できるようにした話
    • （私には）難しい話で、Ruby 開発版で弊社アプリを手元で動かすために四苦八苦した記録です。
    • Ruby の機能を用いて、よく知らない Ruby アプリの挙動を調べるための方法を紹介します。

ならべてみると、どう考えても需要がない気がしますが、気にせず進めます。

デバッグカウンタの導入によるRubyの詳細な挙動調査の紹介

Ruby インタプリタ（のソースコード）にこっそり入っているデバッグカウンタを使って、Ruby プログラムの詳細な挙動を追う方法をご紹介します。

詳細といっても、「あるメソッドがどのメソッドを呼んで...」という情報を事細かくとるわけではなく（取ろうと思えば別の方法で取れます）、Ruby インタプリタに内蔵されている機能を、何を何回使っているか、例えばオブジェクトの生成は何回行ったか、等を調べます。これは、（多分）アプリケーションを改善するためではなく、インタプリタを改善するために取得します。人生長いですから、インタプリタを改善したくなる日も来るかもしれませんので、その際にご活用下さい。

よくある調査の仕方

Ruby プログラムのベンチマークをとろうとすると、多くの場合、プログラムの実行時間をとることが多いと思います。また、ほかにもメモリプロファイラなどを用いることが多いと思います。私が知っているプロファイリング手法を書き出してみます。おそらく、もっといろいろあると思います（あんまりちゃんと Ruby プログラミングしたことないので...）。

  • あるプログラムの実行時間を測る
    • time ruby ... としてプログラムの実行時間を測る
    • 標準添付の benchmark ライブラリを用いて、ブロックの実行時間を測る
    • benchmark/ips や benchmark-driver といったライブラリ使って、コードブロックの実行時間をはかる
    • stackprof などを用いて、Rubyのどのメソッドが処理に時間がかかっているか調べる
    • gprof や perf などのシステムプロファイルをとる
  • メモリの利用法についてのプロファイルをとる
    • memory_profiler によって、メモリ使用量を調べる
    • allocation_tracer によって、どこでどのようなオブジェクトが生成されているかを調べる
    • gc_tracer によって GC ごとのヒープの状況を調べる（だいたい GC.stat や GC.latest_gc_info の情報が取れます）
    • gperftools を使って malloc の詳細な統計を取る
    • valgrind massif によって、メモリ確保の詳細を調べる（いくつかの時点のスナップショットを取得できます）

これらは、単にツールを使うだけですので、状況を手軽に知るにはよい手段です。ただ、これらの機能はインタプリタのプロファイリング支援機能を用いているので、さらにそれ以上の情報が欲しい、と思っても難しいです。いくつか手法はあり、例えば valgrind というツールでは、malloc()（C言語によるメモリ確保関数）を置き換えることで、メモリ確保の詳細な記録をとっています（valgrind では、もっとすごいことをいろいろしていますが、その一例です）。Ruby の TracePoint を使うと、Ruby がサポートしているフックを用いて、例えば「何回メソッド呼び出しが起こったか？」という数は計測可能です。が、導入にはオーバヘッドがとても大きいです。

ただ、例えば「何回、どのようなメソッドやブロックを呼び出したか？」、さらにインタプリタに内蔵されている最適化の仕組み、たとえば「メソッドキャッシュのヒット率は？」といった情報は、既存のツールや言語機能で取ろうとすると、そこそこ難しいです。インタプリタのバイナリを変更するバイナリパッチをあてる、というのが一つの解でしょうか。ただ、それを実現するのは面倒そうです。

デバッグカウンタの準備

そこで、Rubyのソースコードにはデバッグカウンタという仕組みが内蔵されています（入れたの私なんですけど）。 カウンタの宣言と、イベントが発生したときにインクリメントをする処理を書けば終わりです。

// debug_counter.h
// カウンタの宣言部
...
RB_DEBUG_COUNTER(mc_inline_hit)
RB_DEBUG_COUNTER(mc_inline_miss)
...
// カウンタの宣言。同じようにテキトーに追加すればカウンタが増える。
// vm_insnhelper.c
// カウンタのインクリメントの例
...
    /* cache hit! */
    VM_ASSERT(cc->call != NULL);
    // mc_inline_hit は、メソッドキャッシュがヒットした回数をカウント
    // このパスを通っているということは、キャッシュがヒットした、ということなのでカウントアップ
    RB_DEBUG_COUNTER_INC(mc_inline_hit);
    return;

最後に、debug_counter.h にある USE_DEBUG_COUNTER を 1 にして Ruby インタプリタをビルドすれば完成です。

おや、Ruby のビルド方法や miniruby の存在をご存じないですか？　Ruby Hack Challenge の資料をごらん下さい。また、次回の Ruby Hack Challenge イベントへご参加もオススメします。クックパッド株式会社 - connpass をチェックしておいて下さい。

なお、なぜプロファイルカウンタではなく、デバッグカウンタという名前にしているかというと、プロファイルカウンタにしておくと、通常のプロダクション環境でも値が取りたい、などと言われそうだからです。デバッグ用なんで、ビルド時にしか使えません、と言い張るためです。実際、カウントアップするために、いくつか冗長な処理が入っており、少し遅くなってしまいます。

実は、似たような処理は、特定の高速化のための仕組みを入れるごとに、効果を測定するために、毎回カウンタ用変数の用意、カウントアップ、カウンタの表示、のようなことを書いていました（そして、コミット時には余計なコードとして消す）。さすがに毎回こんなことやっているのは、いい加減鬱陶しくなってきたので、一つの仕組みに統一しようと思い、デバッグカウンタとして導入したのでした。

なお、DTrace や SystemTap といった、性能評価フレームワークの上で動作させる、というのも当然考えられますが（実際、それが格好良く、順当だと思いますが）、私が使い方がよくわからなかったのと、性能測定しないとき（つまり、ほとんどの場合）に、オーバヘッドを残さないようにする自信がなかったため、現在のような素朴な実装になっています。

デバッグカウンタの利用

では、ちょっと miniruby を使って次のサンプルプログラムを実行してみましょう。

# sample code
10_000.times{
  s = [Object.new, "foo", {bar: 1}, :baz]
}

実行終了後、とても沢山のカウンタの情報が出てきます。手元の環境では、下記のような出力になりました。 長いですが、どーんと載せます。どーんと読み飛ばして下さい。

[RUBY_DEBUG_COUNTER]    71695 normal exit.
[RUBY_DEBUG_COUNTER]    mc_inline_hit                           19,998
[RUBY_DEBUG_COUNTER]    mc_inline_miss                               3
[RUBY_DEBUG_COUNTER]    mc_global_hit                           10,014
[RUBY_DEBUG_COUNTER]    mc_global_miss                             277
[RUBY_DEBUG_COUNTER]    mc_global_state_miss                         3
[RUBY_DEBUG_COUNTER]    mc_class_serial_miss                         0
[RUBY_DEBUG_COUNTER]    mc_cme_complement                            0
[RUBY_DEBUG_COUNTER]    mc_cme_complement_hit                        0
[RUBY_DEBUG_COUNTER]    mc_search_super                          1,394
[RUBY_DEBUG_COUNTER]    frame_push                              40,244
[RUBY_DEBUG_COUNTER]    frame_push_method                            0
[RUBY_DEBUG_COUNTER]    frame_push_block                        10,000
[RUBY_DEBUG_COUNTER]    frame_push_class                             0
[RUBY_DEBUG_COUNTER]    frame_push_top                               0
[RUBY_DEBUG_COUNTER]    frame_push_cfunc                        30,242
[RUBY_DEBUG_COUNTER]    frame_push_ifunc                             0
[RUBY_DEBUG_COUNTER]    frame_push_eval                              1
[RUBY_DEBUG_COUNTER]    frame_push_rescue                            0
[RUBY_DEBUG_COUNTER]    frame_push_dummy                             1
[RUBY_DEBUG_COUNTER]    frame_R2R                                    1
[RUBY_DEBUG_COUNTER]    frame_R2C                               20,026
[RUBY_DEBUG_COUNTER]    frame_C2C                               10,216
[RUBY_DEBUG_COUNTER]    frame_C2R                               10,000
[RUBY_DEBUG_COUNTER]    ivar_get_ic_hit                              0
[RUBY_DEBUG_COUNTER]    ivar_get_ic_miss                             0
[RUBY_DEBUG_COUNTER]    ivar_get_ic_miss_serial                      0
[RUBY_DEBUG_COUNTER]    ivar_get_ic_miss_unset                       0
[RUBY_DEBUG_COUNTER]    ivar_get_ic_miss_noobject                    0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_hit                              0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_miss                             0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_miss_serial                      0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_miss_unset                       0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_miss_oorange                     0
[RUBY_DEBUG_COUNTER]    ivar_set_ic_miss_noobject                    0
[RUBY_DEBUG_COUNTER]    ivar_get_base                              447
[RUBY_DEBUG_COUNTER]    ivar_set_base                              479
[RUBY_DEBUG_COUNTER]    lvar_get                                     0
[RUBY_DEBUG_COUNTER]    lvar_get_dynamic                             0
[RUBY_DEBUG_COUNTER]    lvar_set                                10,000
[RUBY_DEBUG_COUNTER]    lvar_set_dynamic                             0
[RUBY_DEBUG_COUNTER]    lvar_set_slowpath                            0
[RUBY_DEBUG_COUNTER]    obj_newobj                              46,638
[RUBY_DEBUG_COUNTER]    obj_newobj_slowpath                        212
[RUBY_DEBUG_COUNTER]    obj_newobj_wb_unprotected                   25
[RUBY_DEBUG_COUNTER]    obj_free                                38,775
[RUBY_DEBUG_COUNTER]    obj_promote                              4,872
[RUBY_DEBUG_COUNTER]    obj_wb_unprotect                            35
[RUBY_DEBUG_COUNTER]    obj_obj_ptr                                  0
[RUBY_DEBUG_COUNTER]    obj_obj_embed                            9,266
[RUBY_DEBUG_COUNTER]    obj_str_ptr                                  4
[RUBY_DEBUG_COUNTER]    obj_str_embed                           10,897
[RUBY_DEBUG_COUNTER]    obj_str_shared                              39
[RUBY_DEBUG_COUNTER]    obj_str_nofree                               0
[RUBY_DEBUG_COUNTER]    obj_str_fstr                                 0
[RUBY_DEBUG_COUNTER]    obj_ary_ptr                              9,270
[RUBY_DEBUG_COUNTER]    obj_ary_embed                               17
[RUBY_DEBUG_COUNTER]    obj_hash_empty                               0
[RUBY_DEBUG_COUNTER]    obj_hash_under4                          9,269
[RUBY_DEBUG_COUNTER]    obj_hash_ge4                                 1
[RUBY_DEBUG_COUNTER]    obj_hash_ge8                                 0
[RUBY_DEBUG_COUNTER]    obj_struct_ptr                               0
[RUBY_DEBUG_COUNTER]    obj_struct_embed                             0
[RUBY_DEBUG_COUNTER]    obj_regexp_ptr                               0
[RUBY_DEBUG_COUNTER]    obj_data_empty                               0
[RUBY_DEBUG_COUNTER]    obj_data_xfree                               0
[RUBY_DEBUG_COUNTER]    obj_data_imm_free                            1
[RUBY_DEBUG_COUNTER]    obj_data_zombie                              0
[RUBY_DEBUG_COUNTER]    obj_match_ptr                                0
[RUBY_DEBUG_COUNTER]    obj_file_ptr                                 0
[RUBY_DEBUG_COUNTER]    obj_bignum_ptr                               0
[RUBY_DEBUG_COUNTER]    obj_symbol                                   0
[RUBY_DEBUG_COUNTER]    obj_imemo_ment                               1
[RUBY_DEBUG_COUNTER]    obj_imemo_iseq                               0
[RUBY_DEBUG_COUNTER]    obj_imemo_env                                0
[RUBY_DEBUG_COUNTER]    obj_imemo_tmpbuf                             2
[RUBY_DEBUG_COUNTER]    obj_imemo_ast                                1
[RUBY_DEBUG_COUNTER]    obj_imemo_cref                               0
[RUBY_DEBUG_COUNTER]    obj_imemo_svar                               0
[RUBY_DEBUG_COUNTER]    obj_imemo_throw_data                         0
[RUBY_DEBUG_COUNTER]    obj_imemo_ifunc                              4
[RUBY_DEBUG_COUNTER]    obj_imemo_memo                               0
[RUBY_DEBUG_COUNTER]    obj_imemo_parser_strterm                     1
[RUBY_DEBUG_COUNTER]    obj_iclass_ptr                               0
[RUBY_DEBUG_COUNTER]    obj_class_ptr                                0
[RUBY_DEBUG_COUNTER]    obj_module_ptr                               0
[RUBY_DEBUG_COUNTER]    heap_xmalloc                            32,722
[RUBY_DEBUG_COUNTER]    heap_xrealloc                               20
[RUBY_DEBUG_COUNTER]    heap_xfree                              28,272

沢山出力しちゃうので、使うときは grep などを使ってフィルタリングして下さい。

さて、暗号みたいな名前がイッパイ出てきています。「やっぱり Ruby インタプリタって難しいんだな」と思うかもしれません。安心して下さい。全部わかるのは私しか居ません、多分。そりゃ、私が都合の良いように作ったので、わかるわけがないのです（私も昔、別の言語や OS のよくわからない用語を見て、わからなくて悲しい思いをしたものですが、大抵は作ってる人がその場のノリで決めてるだけから、わからなくて当然だ、と思うと、少し楽になりました。ノリを掴むまでが大変ですね）。ですので、これを機会にちょっと解説してみます。

PID

71695 normal exit

ここは、PID を示しています。プログラムの実行終了時にこの表示を行うのですが、最近の Ruby システムは bundler とかツールを色々使って実行されるため、複数のプロセスから出力されるため、よくわからなくなっちゃうんですよね。そのため、PID を出力するようにしています。

メソッドキャッシュ

[RUBY_DEBUG_COUNTER]    mc_inline_hit                           19,998
[RUBY_DEBUG_COUNTER]    mc_inline_miss                               3
[RUBY_DEBUG_COUNTER]    mc_global_hit                           10,014
[RUBY_DEBUG_COUNTER]    mc_global_miss                             277

この辺は、メソッドキャッシュの利用状況です。メソッドキャッシュというのは、メソッド探索結果をキャッシュしておくことで、メソッド呼び出しを速く実行するという、古典的な手法ですが、それがどれくらい効いているか、を示しています。インラインとかグローバルとかは、まぁいくつかキャッシュの種類があると思って下さい（詳細は「YARV Maniacs 【第 6 回】 YARV 命令セット (3) メソッドディスパッチ」をご覧下さい）。

mc_inline_hit、つまりインラインメソッドキャッシュのヒットした回数を見てみると、19,998 回、mc_inline_miss は 3 回なので、インラインメソッドキャッシュを使っているところでは、驚異の 99.985% のキャッシュヒット率。 キャッシュがあって良かったね、ということになります。

ちなみに、キャッシュミスした3回は、一体どこにあるでしょうか。

まず、インラインメソッドキャッシュが失敗する理由は次の2つです。

  1. まだキャッシュされていなかった（一度もメソッドを呼んでいなかった）
  2. 以前キャッシュしたものにヒットしなかった（例えば、キャッシュしたときと違うクラスのオブジェクトをレシーバとしたメソッド呼び出しとなった）

このサンプルコードは単純なので、2 が起こるようなことはありません。つまり、1 の初期参照ミスだけ探せば良いことになります。

# sample code
10_000.times{
  s = [Object.new, "foo", {bar: 1}, :baz]
}

さて、このサンプルコード中にあるメソッド呼び出しは、次の2つに見えます。

  • 10_000.times
  • Object.new

もう一つはどこにあるでしょうか？　実は、書きながら私もわからなかったので調べてみたのですが、{bar: 1} にありました。なんで Hash リテラルなのにメソッド呼び出しを行っているのでしょうか。実は、Hash リテラルの中身がすべて Symbol や Integer などの特別なリテラルの場合、コンパイル時に配列を作っておき、その配列から hash オブジェクトを生成する、ということをしています。配列から Hash オブジェクトを生成するために、秘密のメソッド（core_hash_from_ary）を呼んでいる、というわけです。

ちょっと考えた結果、少し弄って、メソッドの代わりに新しい命令を作って、それを使うように変えました（r65343。もうメソッドは使わない）。typical な例では 30% 高速化しています。そもそもなぜメソッドにしていたかというと、命令数が多くなると、いくつかの理由で VM の挙動が遅くなるからなのですが、まぁ、これはいいかなぁ、という気分でやり直しました。数要素のハッシュリテラル（要素はすべてシンボルや数値などである場合）のとき、ちょっと速くなります。

フレーム

[RUBY_DEBUG_COUNTER]    frame_push                              40,244

ちょっと飛んで frame です。frame というのは、メソッドやブロックを実行するときに必要になるものです。

ちょっと数えてみましょう。この例だと1万回のブロックの起動＋Object.new メソッドの起動、core_hash_from_ary メソッドの起動がそれぞれ1万回行われるので、これで合計 3 万回。あれ、約1万回足りませんね？　実は、まだ隠れているのが initialize です。どこにも現れていませんが、Object.new を実行すると、デフォルトの initialize メソッドが呼ばれるわけです。こいつは C で実装されています。

その後に出てくる下記の情報ですが、R2R が Ruby で実装された何かのフレーム（以降 Ruby フレーム）から Ruby フレームを作った、R2C が Ruby フレームから C で実装されたなにかのフレーム（以降 C フレーム）を作った、以下同じ、という感じです。

[RUBY_DEBUG_COUNTER]    frame_R2R                                    1
[RUBY_DEBUG_COUNTER]    frame_R2C                               20,026
[RUBY_DEBUG_COUNTER]    frame_C2C                               10,216
[RUBY_DEBUG_COUNTER]    frame_C2R                               10,000

R2C 2万回、というのが、Object.new の呼び出し（ブロックから C で実装した .new を呼んでいる）と、同じく core_hash_from_ary の呼び出しです。C2C 1万回が、Object.new -> initalize の呼び出し。ちなみに、C2R の1万回は、C で実装された times が Ruby で書かれたブロックを呼び出している回数ですね。ぴったり1万回。

オブジェクトの生成

次は、obj_ という prefix のついたカウンタです。ご想像の通り、オブジェクトの数に関係するカウンタです。一部抜粋します。

[RUBY_DEBUG_COUNTER]    obj_newobj                              46,638
[RUBY_DEBUG_COUNTER]    obj_free                                38,775
[RUBY_DEBUG_COUNTER]    obj_promote                              4,872
[RUBY_DEBUG_COUNTER]    obj_obj_ptr                                  0
[RUBY_DEBUG_COUNTER]    obj_obj_embed                            9,266
[RUBY_DEBUG_COUNTER]    obj_str_ptr                                  4
[RUBY_DEBUG_COUNTER]    obj_str_embed                           10,897
[RUBY_DEBUG_COUNTER]    obj_ary_ptr                              9,270
[RUBY_DEBUG_COUNTER]    obj_ary_embed                               17
[RUBY_DEBUG_COUNTER]    obj_hash_empty                               0
[RUBY_DEBUG_COUNTER]    obj_hash_under4                          9,269
[RUBY_DEBUG_COUNTER]    obj_hash_ge4                                 1
[RUBY_DEBUG_COUNTER]    obj_hash_ge8                                 0

newobj は、新しく生成したオブジェクトの数、free は解放した数です。まぁ、わかりやすいですよね。[Object.new, "foo", {bar: 1}, :baz] のコードでは、(1) Object.new (2) "foo" (3) {bar: 1}、それから (4) これらをまとめる配列、の計 4 個のオブジェクトを生成し、それを1万回繰り返すので4万個。obj_newobj の値は 46,638 なので、まぁだいたいあってますね。余分な6000個くらいは、Ruby インタプリタ起動時に生成される内部のオブジェクトです。free は、4万個弱ですが、これは終了時に残っていたものは、Ruby は必要がなければ解放せず、そのままプロセスを終了してしまうので、こうなっています。

obj_obj_... は、Object.new や、ユーザ定義クラスのオブジェクトが「解放」された数になります。そのため、1万個あるはずが、obj_obj_embed の値が1万個切っているのは、プロセスの最後まで残っていたオブジェクトがいるからですね。

さて、suffix に _ptr と _embed がついています。Ruby のデータ構造の話になるのですが、例えば Object の場合、インスタンス変数の数が4以上あると、さらに外部にメモリ領域を確保（malloc）し、そうでなければしない、という構造になっており、それぞれ _ptr、_embed と数えています。オブジェクト生成自は必ず _embed なので、free するときに数を数えているわけです。

str も ary も同じなのでわかりますよね。文字列と配列です。

hash の場合は、ちょっと違って、empty、under4、ge4、ge8 とあります。empty と under4 は文字通り空、4要素未満のハッシュオブジェクトの数（解放時）、ge は greater than or equal to の略で、ge4、ge8 はそれぞれ4以上、8以上のハッシュオブジェクトの数を示しています。なぜ、こんなに細かく見ているかというと、私はハッシュの要素数って、もっと沢山あるものだと思ってたんですが、後で見ますが、少ない要素数のハッシュオブジェクトが支配的だったんですよね。その辺を確認するために入れました。

その他

面倒になってきたので、その他の詳細は https://github.com/ruby/ruby/blob/trunk/debug_counter.h をご参照下さい。頑張ってコメント書きました。

実際のアプリケーションでのデバッグカウンタ

いくつかの実例を見てみます。以前、私が ruby-core メーリングリストに投稿した [ruby-core:89203] FYI: debug counters をベースにご紹介します。デバッグカウンタのデータ詳細は、長いので引用しません。元のメールをご参照下さい。

optcarrot

optcarrot はベンチマークのために作られた、数値演算が支配的なベンチマークです。インスタンス変数アクセスが多いことも特徴的です。

[ruby-core:89203] FYI: debug counters からデータを引用します。

[RUBY_DEBUG_COUNTER]    mc_inline_hit                       89,376,363
[RUBY_DEBUG_COUNTER]    mc_inline_miss                         103,503

これを見る限り、インラインメソッドキャッシュのヒット率は 99% を超えています。ほぼキャッシュにあたっていると思って良いですね。しかし、約 100M 回、つまり 1 億回もメソッドを呼び出してるんですね。

[RUBY_DEBUG_COUNTER]    obj_newobj                             390,384
[RUBY_DEBUG_COUNTER]    obj_free                                14,408
[RUBY_DEBUG_COUNTER]    obj_promote                            270,020

newobj の数は390K個と、たいしたことがありません。特筆すべきは、（上で解説していなかった）promote の数ですね。これは、世代別 GC において、古い世代であり、「おそらく解放されないだろう」とインタプリタが思っているオブジェクトの数であり、普通のアプリでは、この数は（生成されたオブジェクトの数に比べて）ずっと少ないことが期待されます。optcarrot は、「オブジェクトを生成したら（速度的に）負けである」という設計なので、最初にオブジェクトを作っているため、このようになるのではないかと思います。GC の回数が多くなると、現存する promote されたオブジェクトの数が重要になるのですが、optcarrot の場合、GC の発生回数自体が少ないため、問題にならないです。そういえば、GC の回数をこれに入れておくのを忘れていたなあ（→入れました r65359）。

rdoc

Ruby をインストールするときには、Ruby に入っているソースコードを、rdoc コマンドを通してすべて読み込み、ri ドキュメントを生成しています。その挙動を対象アプリにした結果を見てみます。

[ruby-core:89203] FYI: debug counters からデータを引用します。

[RUBY_DEBUG_COUNTER]    mc_inline_hit                     77,428,972
[RUBY_DEBUG_COUNTER]    mc_inline_miss                       398,444

これも、インラインメソッドキャッシュヒット率高いですね。

[RUBY_DEBUG_COUNTER]    obj_newobj                       162,910,687
[RUBY_DEBUG_COUNTER]    obj_promote                        7,289,299

オブジェクトは、95% promote していない、つまり若いまま死んでいくので、しっかり世代別 GC が効いています。しかし、やはり沢山オブジェクト使いますね。

[RUBY_DEBUG_COUNTER]    obj_obj_ptr                        8,505,888
[RUBY_DEBUG_COUNTER]    obj_obj_embed                      4,395,142
[RUBY_DEBUG_COUNTER]    obj_str_ptr                        6,345,111
[RUBY_DEBUG_COUNTER]    obj_str_embed                     63,065,862
[RUBY_DEBUG_COUNTER]    obj_str_shared                     7,865,747
[RUBY_DEBUG_COUNTER]    obj_ary_ptr                        5,016,497
[RUBY_DEBUG_COUNTER]    obj_ary_embed                     35,748,852
[RUBY_DEBUG_COUNTER]    obj_hash_empty                     3,632,018
[RUBY_DEBUG_COUNTER]    obj_hash_under4                    4,204,927
[RUBY_DEBUG_COUNTER]    obj_hash_ge4                       2,453,149
[RUBY_DEBUG_COUNTER]    obj_hash_ge8                         841,866
[RUBY_DEBUG_COUNTER]    obj_struct_ptr                            99
[RUBY_DEBUG_COUNTER]    obj_struct_embed                   1,640,606

オブジェクトの種類別に見ると、文字列、配列が多いことがわかります。その次は Object かな。Struct も 1.6M 個作っていますね。embed が多いので、あまり大きくないオブジェクトが多いみたいですね。

discourse

discourse は Rails アプリケーションの一つで、ベンチマークプログラムを整備している（bench.rb）ので、そのベンチマークを用いた結果です。いくつかのページ（6ページ）に対して、ab を用いて 500 回アクセスするので、計 3,000 アクセスをエミュレーションしています。

同じく [ruby-core:89203] FYI: debug counters からデータを引用します。

[RUBY_DEBUG_COUNTER]    frame_push                     1,011,877,345
[RUBY_DEBUG_COUNTER]    frame_push_method                456,075,698
[RUBY_DEBUG_COUNTER]    frame_push_block                  79,600,045
[RUBY_DEBUG_COUNTER]    frame_push_class                       8,230
[RUBY_DEBUG_COUNTER]    frame_push_top                         3,360
[RUBY_DEBUG_COUNTER]    frame_push_cfunc                 460,186,970
[RUBY_DEBUG_COUNTER]    frame_push_ifunc                  15,987,591
[RUBY_DEBUG_COUNTER]    frame_push_eval                        8,956
[RUBY_DEBUG_COUNTER]    frame_push_rescue                      6,452
[RUBY_DEBUG_COUNTER]    frame_push_dummy                          43

とりあえず、frame_push のカウントが 1G、つまり 10 億回です。HDD のサイズだと、たいしたことの無い数ですが、何かを 10 億回繰り返すというのは凄いですね。数分で終わるベンチマーク。まぁ、1Ghz のプロセッサなら、1秒あれば、1G回の計算はできるのですが。

1G 回として、ちょっと frame_push にかかる時間を見積もってみます。1Ghz の CPU を前提とします。

  • 10 cycle、つまり 10ns かかるとすると、1G 回で 10 秒。
  • 100 cycle、つまり 100ns かかるとすると、1G 回で 100 秒。

結構な時間です。実際は、空のメソッド呼び出しおよびメソッドからのリターンで 50 cycle 程度なので、もうちょっと速くしておきたいですね。フレームを積む作業を軽量化する、フレームを積む回数を減らす、の2通りの高速化手法が考えられます。

後続する frame_push_xxx というのは、積むフレームの種類なのですが、method と cfunc が多いですね。それぞれ、Ruby で書かれたメソッド、C で書かれたメソッドを呼んだ、ということです。若干、cfunc のほうが多いのは、実は結構驚きの結果でした。というのも、Ruby で記述されたメソッドをいかに速くするか、という高速化に重点を置いていたんですが、C で書かれたメソッドの呼び出しはあまり取り組んでいなかったためです。cfunc がこれだけ多いなら、このようなメソッドの高速化もちゃんと取り組まないといけないですね。ちゃんと計測しましょう、という話でした。

[RUBY_DEBUG_COUNTER]    obj_newobj                       162,910,687
[RUBY_DEBUG_COUNTER]    obj_free                         161,117,628
[RUBY_DEBUG_COUNTER]    obj_promote                        7,289,299
[RUBY_DEBUG_COUNTER]    obj_wb_unprotect                      83,599
[RUBY_DEBUG_COUNTER]    obj_obj_ptr                        8,505,888
[RUBY_DEBUG_COUNTER]    obj_obj_embed                      4,395,142
[RUBY_DEBUG_COUNTER]    obj_str_ptr                        6,345,111
[RUBY_DEBUG_COUNTER]    obj_str_embed                     63,065,862
[RUBY_DEBUG_COUNTER]    obj_ary_ptr                        5,016,497
[RUBY_DEBUG_COUNTER]    obj_ary_embed                     35,748,852
[RUBY_DEBUG_COUNTER]    obj_hash_empty                     3,632,018
[RUBY_DEBUG_COUNTER]    obj_hash_under4                    4,204,927
[RUBY_DEBUG_COUNTER]    obj_hash_ge4                       2,453,149
[RUBY_DEBUG_COUNTER]    obj_hash_ge8                         841,866

オブジェクトの数は、162M 個と、やはり多いですね。ハッシュオブジェクトの要素爽雨を見ると、ほぼ 8 要素未満で、8 要素以上は 7.5% しかありません。小さな Hash 値向けの高速化は導入の価値がありそうです（ハッシュオブジェクト自体、162M 個中の 11M 個なので、どの程度効くかは微妙ですが）。

クックパッドアプリを手元で調査できるようにした話

さて、では弊社のクックパッドアプリはどうなのよ、と気になるところです。ただ、そもそも手元でベンチマークを行う環境を作成するのがいくつかの理由で困難でした。

一番大きな問題は、私が Ruby on Rails アプリの読み解き方を知らない、というものなのですが、まぁそれは置いといて、手元で動かすためには、開発用に用意している環境（DB やサービス）を使うのですが、それらはベンチマークで負荷をかけるようなことは考慮していないためです。

なお、クックパッドの開発環境についての詳細はこちらをご覧下さい：開発環境のデータをできるだけ本番に近づける

mysql2_recorder

一番単純な解決策は、開発用DB（等）をベンチマーク実行環境にコピーすることですが、そこそこデータ量も大きく、必要なデータを選別する、というのも面倒です。そこで、一度アクセスして結果を取得し、どこかに結果をキャッシュすることにしました。ただ、私は Rails のソースコードがよくわからないので、どこにどうやってキャッシュしておけばいいかよくわかりません。一番良さそうなのは、ActiveRecord (AR) のキャッシュ機構をうまいこと利用することでしょうか。でも、AR って大きそうでよくわからない。

一度、Rails アプリから DB（弊社の場合、MySQL）のつながりがどうなっているか考えてみました。

(ruby の世界) rails アプリ  -> ActiveRecord (sql を組み立ててリクエスト) -> Mysql2
->
(C の世界) Mysql2 の C extension -> libmysqlclient-dev
->
(network の外側) MySQL server

こんな感じでリクエストが飛んで、結果を取ってきます。

そこで、Rails 層がわからないのなら、AR がアクセスしている Mysql2 を見れば、なんとなくわかるんじゃないかと思いました。そこそこ C で書いてあるし、小さいし。多分、データのやりとりしている部分って少ないんじゃ無いかとふんだんですよね（低レイヤ脳）。

Mysql2 の機能を見ると、query メソッドが色々やってくれそうですが、そこから先は、libmysqlclient-dev のほうに処理を丸投げしているようで手が出せない（さすがにこれ以降は手をだすのが面倒そうだ）、というわけで、Mysql2 あたりで結果を貯めておき、既知のクエリには貯めておいた結果を返すようにすることにしました。

Rails がどのように Mysql2 を使っているかわからないので、まずは小さな Rails アプリを作り、挙動を観察してみることにしました。 この場合、Mysql2 側のメソッドがどんなふうに呼ばれているか知りたいため、TracePoint を利用します。

# この行をどこかに挟んでおく。私は mysql2.gem の mysql2.rb に追加してみました。
TracePoint.new(:call, :c_call){|tp| 
  if /mysql2/ =~ tp.path # 見たいところだけ情報を出す
    p tp # 呼び出し元の情報を知るために、caller を出してもいいですね。
  end
}.enable

この1行を、どこか適当なところに挟んでおくと、ファイル名が mysql2 を含む行のメソッドが呼ばれたりすると、情報が表示されます。tp.defined_class などを使って、クラスで絞ったりするのもいいかもしれませんね。そんな感じで、なるほどこうやって AR から呼ばれるのか、ということを調べていくと、どうやら Mysql2::Client#query(sql) が Mysql2::Result を返し、しかも実際のデータの取得は Mysql2::Result#to_a の結果しか使っていないことがわかりました。シメシメ。

つまり、Mysql2::Client#query(sql) をフックし、Mysql2::Result#to_a の結果をすぐに取り出してしまい、その値をキャッシュしてやれば、以降は to_a の結果を返す FakeResult でも返してあげれば良さそうです。というわけで、作った結果がこちら: mysql2_recorder/mysql2_recorder.rb。

ベンチマークをとりたい、という必要性から、あまりワークロードを変えたくないのですが、まぁ少しくらいの変更ならいいだろう、と思ってよしとしました。

これで、開発用DBから一度取得したデータは、二度とアクセスしないでよくなりました。

あ、select 文しか対応しないようにしています。ベンチマークが目的なので。それ以外は通しますが、継続的に発行している select 以外のクエリはないように、ベンチマークのシナリオを構成しています。こういうログをじっと見るのも楽しいですね。

クエリは変るよ

「これで、開発用DBから一度取得したデータは、二度とアクセスしないでよくなりました」、と思って走らせてみると、同じページへの2度目のリクエストでも、SQL クエリは変るんですね。

いくつかの典型的なパターンと、その今回の対処法についてご紹介します。

  • 現在時刻を含めたクエリを発行している → キャッシュするとき、日付っぽいデータはマスクしました L110
  • AR のクエリはクエリ発行元の情報が入るので、同じクエリでも同一クエリにならない → キャッシュするとき、コメントっぽいデータはマスクしました L111
  • アプリケーションコード中に Array#shuffle とか使っている → srand(0) することで乱数を潰しました L5

他にも、どうしてもわからないところはコードを削ったりしています。 いや本当に役に立たない情報ですね...。

そういえば、エラーが出ても、バックトレース情報が潰されてしまい、どこで何が起こっていたかわからないことがありました。今回は、具体的には　ActiveRecord::StatementInvalid が、その前に出た例外を上書きしてしまう、という問題でした。こういう時にはバックトレースを知りたいだけなので、慌てず騒がず、

TracePoint.new(:raise){|tp| pp [tp.raised_exception, caller]}.enable

という一行を、どこかアプリケーションの起動処理の中に挟み込んでおくことで、例外が本当に起こった場所を探しました。例外が発生するたびに、情報を表示してくれます。実は、Rails アプリでは結構な頻度で例外が飛び交っているため、例外クラスを見てフィルタリングするなどをしてもいいでしょう。

TracePoint の解説みたいな記事になってしまった。

もう安心？

弊社のサービスは、他のサービスと連携しているので、その連携先にも迷惑をかけないようにしなければなりません。これについてはいくつか案を考えたんですが、最終的に VCR で十分、という結論になりました。めでたしめでたし。

が、評価で使いたかった Ruby 2.6 （開発版）ではうまく動かすことができなかったので、結局これはまだ調整中です...。

肝心のデバッグカウンタは？

では、その上で、とりあえずデバッグカウンタの中身を見たらどうなるでしょうか。

ベンチマークアプリのシナリオは次の通りです。

  • ある日、ある時間のアクセスログから、この環境で動作させることができるページを 1,000 個取ってくる
  • その1セットへのアクセスを行う、というのを 5 回繰り返す

ということにしました。都合5,000ページのアクセスです。デバッグカウンタの値はどんなもんでしょうか。

mc_inline_hit                    6,008,617,014
mc_inline_miss                     482,996,246
frame_push                       7,670,138,991
obj_newobj                       3,564,050,452

さすがに凄い数ですね。7.6G回のフレームを積んで、下ろす作業を想像しただけでも気が遠くなります。 オブジェクトも 3G 個も作っているんですね。最低 40 Byte 必要なので、少なくとも 120 GB のメモリ使用（のべ）が起こったということになります。他にも malloc によってメモリを使っているので、もっともっとメモリを使っています。これらは自動的に GC によってメモリが解放されています。

こういうのを参考にしながら、次はどういうことをしようかなぁ、と考えます。

おわりに

本稿では、誰も幸せにならなそうな2つのトピックをご紹介しました。

  • デバッグカウンタの導入によるRubyの詳細な挙動調査の紹介
    • 内部の細かい挙動を追うためのカウンタの紹介。
    • 見てきたとおり、Ruby の再ビルドが必要です。カウンタの追加は簡単そうでしょう？
  • クックパッドアプリを手元で調査できるようにした話
    • ベンチマーク用に mysql2 のクエリをキャッシュする仕組みを用意しました。
    • TracePoint を用いた、よく知らないソフトウェアの調査方法を紹介しました。

一つ一つは単純なテクニックだったと思いますが、ちゃんと解説しようとすると長いですね。 こんな感じで、中身を確認しながら Ruby の開発を進めています。

たまにはこんな、インタプリタの泥臭い話、でした。