rubygems を 1.5 倍に高速化した方法(stackprof --d3-flamegraph の使い方)

タイトルは釣りです。明日 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 を開くと、フレーム(炎)というか山のような図が出てきます。

f:id:ku-ma-me:20200911223800p:plain
stackprof --d3-flamegraph の出力(html)

これは、スタックフレームを表現しています。下から 2 番目が起動スクリプトの bin/gem があり、そこから呼び出されているメソッドが上に積み重なっています。

勘違いしやすいですが、このグラフは時系列とは一切関係ありません。左から右に時間が進んでいる図ではありません。実行中のスタックフレームを定期的に観測し、そのスタックフレームを辞書順にソートして並べたものになっています。

見方にコツがあります。例でいうと、下から 6 番目の Gem::GemRunner#run とその上の Gem::CommandManager#run は、横幅がほとんど同じです。これは、Gem::GemRunner#runGem::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% も占めていることがわかります。

f:id:ku-ma-me:20200911224103p:plain
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 に参加する人たち、ぜひがんばってください。

*1:--d3-flamegraph の前から flamegraph を生成する方法はあったのですが、いまいち素直に使えなかったので。