簡単にApacheモジュールのプロファイルをとってみよう

ApacheモジュールはApache httpdに組み込んで使うために、いまいちモジュール単体のテストやプロファイルやデバッグがやりにくい印象があります。

デバッグに関しては以前gdbを使った方法を紹介しましたが、今回は色々あるプロファイラの中で比較的楽にプロファイルが得られるOProfileを使ったプロファイルの取り方を紹介したいと思います。非常に簡単です。

ちなみに、プロファイラをかます事で対象そのものに影響を大きく与えてはいけないという意味で、この話だけでも研究になりそうですが、あまり深入りし過ぎるとまた別の方向にいってしまいそうなので、今回はそういった精度よりもどれだけ簡単にできるかというところに重点を置いた方法を紹介したいと思います。

OProfileでApache httpdをプロファイル

まずは、OProfileがインストールされている状態で以下のコマンドによりプロファイルの準備をします。近頃のディストリビューションだとyumやapt-getですぐインストールできるでしょう。

また、プロファイルしたいバイナリは-gや-O0によりデバッグシンボルを残した状態でコンパイルしていることを忘れないで下さい。stripしたバイナリとかではほとんど情報は取れません。

[program lang=’bash’ escaped=’true’]

sudo opcontrol --no-vmlinux
sudo opcontrol --start

[/program]

この状態で、プロファイルを取りたいモジュールが入ったApache httpdを起動させます。そして、Apacheなのでベンチマークツールなどにより負荷をかけます。

今回は「mod_mrubyとmod_rubyの比較のためにプロファイルしてみよう」という目的で、それぞれのモジュールを組み込んだ状態で、mod_mrubyで処理されるhelloworldスクリプトとmod_rubyで処理されるhelloworldスクリプトそれぞれに同じ数(10000回)だけリクエストを処理させました。そして、負荷をかけ終わった後は、以下のようにプロファイラを停止します。

[program lang=’bash’ escaped=’true’]

sudo opcontrol --stop

[/program]

そして、プロファイルしたいApacheモジュールの.soバイナリのパスを指定してプロファイルを見てみましょう。

今回の場合だと、mod_mrubyとmod_ruby、さらに、mod_rubyからダイナミックリンクされているlibruby.soの情報が欲しいはずです(mod_mrubyはスタティックにmrubyインタプリタをリンクしているため)。その場合は、以下のように該当するバイナリパスを複数指定することで、それぞれのバイナリの処理のおおよそのパフォーマンス比較が可能になります。

[program lang=’bash’ escaped=’true’]

sudo opreport /etc/httpd/modules/mod_ruby.so /etc/httpd/modules/mod_mruby.so /usr/lib/libruby.so

[/program]

すると以下のような結果が得られます。

[program lang=’text’ escaped=’true’]

  samples¦      %¦
------------------
   324659 53.7996 libruby.so.1.9.1
   180762 29.9543 mod_mruby.so
    98039 16.2461 mod_ruby.so

[/program]

libruby.so.1.9.1の処理を占める割合が多い事がわかります。さらにシンボル(関数名)単位で見て行きましょう。その場合は-lオプションを指定します。

[program lang=’bash’ escaped=’true’]

sudo opreport -l /etc/httpd/modules/mod_ruby.so /etc/httpd/modules/mod_mruby.so /usr/lib/libruby.so

[/program]

すると以下のような結果が得られるます。

[program lang=’text’ escaped=’true’]

samples  %        app name                 symbol name
53510     8.8672  libruby.so.1.9.1         st_lookup
50795     8.4173  mod_mruby.so             mrb_sym2name_len
22249     3.6869  mod_mruby.so             yyparse
21571     3.5746  libruby.so.1.9.1         vm_exec_core
20125     3.3349  libruby.so.1.9.1         ruby_yyparse
12161     2.0152  libruby.so.1.9.1         ruby_sip_hash24
11266     1.8669  libruby.so.1.9.1         st_foreach
8647      1.4329  libruby.so.1.9.1         __i686.get_pc_thunk.bx
6988      1.1580  libruby.so.1.9.1         rb_newobj
6537      1.0833  mod_ruby.so              ruby_type_handler
6175      1.0233  mod_mruby.so             __i686.get_pc_thunk.bx
6138      1.0171  libruby.so.1.9.1         slot_sweep
5788      0.9591  libruby.so.1.9.1         .plt
5093      0.8440  mod_mruby.so             parser_yylex
4943      0.8191  mod_ruby.so              rb_init_apache_request
4933      0.8175  libruby.so.1.9.1         rb_funcall
4559      0.7555  libruby.so.1.9.1         iseq_setup
4519      0.7488  libruby.so.1.9.1         gc_marks
4446      0.7368  libruby.so.1.9.1         rb_funcall2
4428      0.7338  mod_ruby.so              ruby_handler_0
4403      0.7296  mod_ruby.so              ruby_handler_internal
4357      0.7220  mod_mruby.so             nextc
4058      0.6725  libruby.so.1.9.1         rb_check_funcall
3948      0.6542  mod_ruby.so              .plt
3933      0.6517  mod_mruby.so             mrb_run
3918      0.6493  mod_ruby.so              ruby_child_cleanup
3852      0.6383  libruby.so.1.9.1         vm_call0
・
・
・

[/program]

mod_mrubyの場合はmrb_sym2nam_len()の処理が占める割合が多いんだなぁと分かります。例えばこのように得られた関数に最適化の余地があれば、そこを改善することで大幅にパフォーマンス改善することも可能になるでしょう。CRubyのruby_yyparseとmrubyのyyparseはほとんど同じなんだなぁとか、mod_ruby+libruby.so側はmod_mrubyと比べて色々な関数が呼ばれている事も分かりますね。

また、opannotateコマンドを使う事で、ソースコードレベルやさらにはアセンブリレベルでプロファイラが可能ですので、上記のコマンドに加えてopannotateの-sや-aオプションで結果を眺めると面白いと思います。

まとめ

このように、非常に簡単にApacheモジュールのプロファイルを取る方法を紹介しました。これで、よりC言語によるOSやmiddlewareまわりの実装が捗りますね。