タイトルは釣りです。明日 ISUCON 10の予選 があると小耳に挟んだので、Ruby で参加する人が絶対に抑えておくべき？ Ruby 高速化の tips をひとつ。stackprof --d3-flamegraph のご紹介です。
例題
ちょうど今日、gem install aws -sdk にかかる時間を 37 秒から 24 秒ほどに高速化しました。
変更前:
$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real 0m37.104s
user 0m36.952s
sys 0m0.333s
変更後:
$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real 0m23.905s
user 0m23.740s
sys 0m0.365s
stackprof --d3-flamegraph ってやつを使ったら 2 時間くらいでできました。
stackprof の使い方
このあたりはみんな知ってると思うのでざっくりと。
対象である gem コマンドに StackProf.run(...) do ... end を挟み込みます。rack だったら use StackProf::Middleware でしょうか。
diff --git a/bin/gem b/bin/gem
index baf607308..6a508e989 100755
--- a/bin/gem
+++ b/bin/gem
@@ -11,8 +11,13 @@
args = ARGV.clone
+require 'stackprof'
+StackProf.run(mode: :cpu, out: 'stackprof.dump', raw: true) do
+
begin
Gem::GemRunner.new.run args
rescue Gem::SystemExitException => e
- exit e.exit_code
+ e.exit_code
+end
+
end
raw: true というのが最重要ポイントです。あと、exit すると stackprof.dump が出力されないようなので、少しだけいじっています。
実行する。
$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real 0m36.562s
user 0m36.418s
sys 0m0.313s
stackprof.dump ができていると思うので、stackprof コマンドで結果を見ます。
$ stackprof stackprof.dump
==================================
Mode: cpu(1000)
Samples: 3543 (0.06% miss rate)
GC: 340 (9.60%)
==================================
TOTAL (pct) SAMPLES (pct) FRAME
567 (16.0%) 374 (10.6%) Gem::Version#<=>
446 (12.6%) 349 (9.9%) Gem::Requirement.parse
287 (8.1%) 287 (8.1%) (sweeping)
498 (14.1%) 257 (7.3%) URI::Generic#hash
227 (6.4%) 227 (6.4%) Gem::Version#canonical_segments
1145 (32.3%) 198 (5.6%) Gem::Resolver::APISpecification#initialize
630 (17.8%) 184 (5.2%) Gem::Requirement#initialize
172 (4.9%) 172 (4.9%) Gem::Version.new
241 (6.8%) 136 (3.8%) URI::Generic#component_ary
842 (23.8%) 128 (3.6%) Gem::Dependency#initialize
131 (3.7%) 106 (3.0%) Gem::Platform#=~
714 (20.2%) 84 (2.4%) Gem::Requirement.create
81 (2.3%) 76 (2.1%) URI::Generic#component
156 (4.4%) 75 (2.1%) Gem::Version#hash
3070 (86.6%) 70 (2.0%) Gem::Resolver#search_for
52 (1.5%) 52 (1.5%) Gem::Platform.local
412 (11.6%) 51 (1.4%) Gem::Requirement#satisfied_by?
47 (1.3%) 47 (1.3%) Gem::Version#_version
46 (1.3%) 45 (1.3%) Gem::Requirement#none?
564 (15.9%) 44 (1.2%) Gem::Dependency#match?
44 (1.2%) 44 (1.2%) Gem::Resolver::Specification#initialize
42 (1.2%) 42 (1.2%) (marking)
42 (1.2%) 42 (1.2%) Gem::Platform.new
33 (0.9%) 33 (0.9%) Gem::Resolver::DependencyRequest#name
33 (0.9%) 30 (0.8%) Gem::StubSpecification#data
30 (0.8%) 30 (0.8%) Gem::Resolver::ActivationRequest#initialize
28 (0.8%) 28 (0.8%) Gem::Version#prerelease?
26 (0.7%) 26 (0.7%) Gem::Dependency#requirement
24 (0.7%) 24 (0.7%) URI::Generic#userinfo
1765 (49.8%) 22 (0.6%) Gem::Resolver::APISet#find_all
なるほど、Gem::Version#<=> がボトルネック なんですね。じゃあこれを高速化しましょう！Gem::Version#<=> のコードを見て……という前に考えるとよいことがあります。
このメソッドはバージョン番号の比較をする演算なので、それ自体がすごく遅いとは考えにくいです。そういうのを速くしようとすると、近視眼的で hacky な最適化になりがちです。どの当たりに時間がかかっているのか、もうすこし大局的に眺めてみましょう。
stackprof --d3-flamegraph の使い方
そこで、flamegraph を使ってみます。次のように実行します。
$ stackprof --d3-flamegraph stackprof.dump > stackprof.html
このとき、
.../lib/stackprof/report.rb:197:in `print_d3_flamegraph': profile does not include raw samples (add `raw: true` to collecting StackProf.run) (RuntimeError)
のようなエラーが出たら、上述の raw: true を付け忘れているので、直して再プロファイルしてください。
この html を開くと、フレーム（炎）というか山のような図が出てきます。
stackprof --d3-flamegraph の出力（html）
これは、スタックフレームを表現しています。下から 2 番目が起動スクリプト の bin/gem があり、そこから呼び出されているメソッドが上に積み重なっています。
勘違いしやすいですが、このグラフは時系列とは一切関係ありません 。左から右に時間が進んでいる図ではありません。実行中のスタックフレームを定期的に観測し、そのスタックフレームを辞書順にソートして並べたものになっています。
見方にコツがあります。例でいうと、下から 6 番目の Gem::GemRunner#run とその上の Gem::CommandManager#run は、横幅がほとんど同じです。これは、Gem::GemRunner#run は Gem::CommandManager#run を呼び出しており、前者の実行時間は後者の実行時間とほとんど同じ、という意味です。よって、Gem::GemRunner#run のコードを最適化しようと思ったときに考えるべきなのは、「Gem::CommandManager#run の呼び出し回数を減らせないか」ということです。しかしコードを見ると、前者は後者を 1 回呼び出しているだけでした。つまり、GemRunner#run を何年眺めても何の高速化もできそうにないということになります。
実際の --d3-flamegraph の結果を置いておきます。
rubygems-stackprof-d3-flamegraph.netlify.app
高速化できそうなところを探す
ここからは結局、気合（デバッグ プリント）です。
このグラフはわりと横幅が同じところが多く、上の方には Gem::Resolver クラスのメソッドがいっぱい並んでいます。aws -sdk は大量の依存を持つので、依存関係の解決に時間がかかっているのは直感にあいますね。一番横幅が長そうな子供を選んでたどっていくと、find_all というメソッドがいくつか並んだあとで、Gem::Resolver::APISpecification#initialize が 26.347% も占めていることがわかります。
Gem::Resolver::APISpecification#initialize を発見したところ
呼び出し元の Gem::Resolver::APISet#find_all と合わせてみると、Gem::Resolver::APISpecification というのは、rubygems .org のサーバから送られてきたデータをオブジェクト化したもののように見えます。いくつかデバッグ 出力を挟んで実行してログを観察すると、中身がまったく同じ Gem::Resolver::APISpecification インスタンス を何回も作ってる気配を感じました。この手のオブジェクトは中身を破壊的に変更することはなさそうなので、生成したオブジェクトを使い回せるのでは？と考えて、オブジェクト生成をメモ化する魔法の 7 行を書いてみます。
@@cache = {}
def self.new(set, api_data)
cache_key = [set, api_data]
cache = @@cache[cache_key]
return cache if cache
@@cache[cache_key] = super
end
再実行。
$ time ruby -I lib bin/gem install --no-doc aws-sdk
Successfully installed aws-sdk-3.0.1
1 gem installed
real 0m25.387s
user 0m24.436s
sys 0m0.354s
やったね。破壊的操作がないことを確かめるため、各フィールドを freeze してもテストが通ることを確認。まあ大丈夫じゃないかな……ということで PR を送って無事マージされました（もしどこかで破壊してて動かなくなってたらごめんね！）。
github.com
修正後の flamegraph
修正後の flamegraph も置いておきます。
rubygems-stackprof-d3-flamegraph.netlify.app
Gem::Resolver::APISpecification#initializeの代わりにGem::Resolver::APISpecification.newが来るようになりました。割合も 15.249% に減っています。
ここからsuperでたまにGem::Resolver::APISpecification#initializeを呼んでいるはずなのですが、定期的な観測にひっかからないほどレアになったということでしょう（たぶん）。
なお、デバッグ プリントからの推測ですが、gem install は、公開されているすべてのバージョンのメタ情報（依存関係情報）をフェッチしてきて、すべてオブジェクト化してから依存関係を解決するようです。これは公開バージョンが増えるほど遅くなりそうなので、まだまだ改善の余地がありそうです。
まとめ
stackprof --d3-flamegraph のご紹介でした。実はこの機能を作ったのは自分なので、自慢です *1 。でも役に立つと思います。
Ruby で ISUCON に参加する人たち、ぜひがんばってください。
