Skip to content

Instantly share code, notes, and snippets.

@wanabe

wanabe/gist:66642ae87c52f9bebf3d06a4f8c55b43

Last active February 18, 2021 15:45
Show Gist options

  • Select an option

    Learn more about clone URLs
  • Save wanabe/66642ae87c52f9bebf3d06a4f8c55b43 to your computer and use it in GitHub Desktop.

Select an option

Learn more about clone URLs
Save wanabe/66642ae87c52f9bebf3d06a4f8c55b43 to your computer and use it in GitHub Desktop.
Download ZIP
現状の Ruby で MJIT 有効にしたときの Rails のパフォーマンスのネックを探る作業記録
Raw
gistfile1.md

この文章は

題名の通り、「現状の Ruby で MJIT 有効にしたときの Rails のパフォーマンスのネック」を探していきたい、という作業記録の文です。 まったく未完成で書きながら作業しているので、ネックが見つからないまま終わる可能性はとても高いです。 それどころかいつまで続くかも決めていないので、結論すら出ない可能性も十分あります。

なお、ここでいう "MJIT" はマージされた YARV-MJIT のことで、元祖の方を呼ぶことがあれば便宜上 RTL-MJIT と呼ぶことにします。

現状確認

2018/03/11 現在の ruby r62719 で、MJIT を有効にしたときに、Rails が劇的に早くなるということはなく、それどころか遅くなるケースもあるようです。

ただこれは「それはそうだよね」って話で、

  • Rails いろいろ絡まってて複雑
    • 生成する JITed なコードもたくさん
    • 規模が大きいので、コンパイルする時間もかかりそう
  • MJIT はまだマージされたばかり
    • 最適化はまだやることやれることがあるらしい
    • いろいろなアプリケーションでの確認はまだまだこれから

というあたりを考えると無理もないことだとは思います。

しかし原因は気になるので、どのあたりに問題がありそうか軽く見ていきたいと思っています。

テストプログラム

幸いにも、小さい rails アプリを作ってベンチも取れるようにしてくれている方がいらっしゃいました。https://twitter.com/schneems/status/971419943244828672 この手順でおおむね作成しつつ、動かないところなんかを少し直したものがこちら。https://github.com/wanabe/rails-new-benchmark

実行してみますと

$ TEST_COUNT=3000 RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 bundle exec derailed exec perf:test
Booting: production
Endpoint: "/"
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
       user     system      total        real
3000 requests  3.793371   0.060812   3.854183 (  3.854026)
$ TEST_COUNT=3000 RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 RUBYOPT='--jit' bundle exec derailed exec perf:test
Booting: production
Endpoint: "/"
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
       user     system      total        real
3000 requests  5.150552   0.130079   9.967233 (  5.283125)

なるほど確かに、--jit オプションをつけた方が時間がかかっています。

benchmark_driver

さてでは、JIT をちょっとだけ有効にしたときにどうなるか、そこから徐々に有効範囲を広げていくとどうなるか、見てみたいと思います。 ということで、JIT のキャッシュ数を --jit-max-cache オプションで換えたときの挙動を見てみます。

このとき、いろいろコマンドを組み立てたり値を比較したり平均取ったりという処理が面倒なので、benchmark_driver gem を使ってみることにします。 こんな rake タスクを作ってみました。https://github.com/wanabe/rails-new-benchmark/commit/1154e768d1a3c08d5333cc130d86f304ea82c357#diff-0b9d45e82f4c56e0cc47bbd9978f375b --jit-min-calls=1 にしているのはそれほど意味はありません。 こちらが実行例です。

$ RAILS_ENV=production bundle exec rake bench SIZES="1 2 4 8 16 32 64 128 256 512 1024"
Booting: production
Endpoint: "/"
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
Warming up --------------------------------------
               bench                                          667.489 i/s
Calculating -------------------------------------
                     system,--jit,--jit-min-calls=1,--jit-max-cache=1  system,--jit,--jit-min-calls=1,--jit-max-cache=2  system,--jit,--jit-min-calls=1,--jit-max-cache=4  system,--jit,--jit-min-calls=1,--jit-max-cache=8  system,--jit,--jit-min-calls=1,--jit-max-cache=16  system,--jit,--jit-min-calls=1,--jit-max-cache=32  system,--jit,--jit-min-calls=1,--jit-max-cache=64  system,--jit,--jit-min-calls=1,--jit-max-cache=128  system,--jit,--jit-min-calls=1,--jit-max-cache=256  system,--jit,--jit-min-calls=1,--jit-max-cache=512  system,--jit,--jit-min-calls=1,--jit-max-cache=1024 
               bench                                          824.186                                           839.946                                           844.265                                           854.431                                            743.894                                            619.337                                            620.152                                             620.418                                             628.639                                             635.307                                              618.412 i/s -      2.002k times in 2.429063s 2.383486s 2.371292s 2.343079s 2.691244s 3.232490s 3.228241s 3.226856s 3.184658s 3.151231s 3.237325s

Comparison:
                            bench
system,--jit,--jit-min-calls=1,--jit-max-cache=8:       854.4 i/s 
system,--jit,--jit-min-calls=1,--jit-max-cache=4:       844.3 i/s - 1.01x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=2:       839.9 i/s - 1.02x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=1:       824.2 i/s - 1.04x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=16:       743.9 i/s - 1.15x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=512:       635.3 i/s - 1.34x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=256:       628.6 i/s - 1.36x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=128:       620.4 i/s - 1.38x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=64:       620.2 i/s - 1.38x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=32:       619.3 i/s - 1.38x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=1024:       618.4 i/s - 1.38x  slower

ここから、キャッシュ 8 個までであればむしろ JIT により速くなっている（かもしれない）が、16 個のあたりでがくんと下がり、32 個になるともっと下がり、それ以上キャッシュが増えてもそれほど変わらない、という結果が見て取れます。 つまり、上位 8-32 位の JIT 化されたメソッドの中に、何か問題がありそうです。 そこで、もう少し細かめに見ていきます。

$ RAILS_ENV=production bundle exec rake bench SIZES="$(seq 8 1 32)"
Booting: production
Endpoint: "/"
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/work/foo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
Warming up --------------------------------------
               bench                                          617.075 i/s
Calculating -------------------------------------
                     system,--jit,--jit-min-calls=1,--jit-max-cache=8  system,--jit,--jit-min-calls=1,--jit-max-cache=9  system,--jit,--jit-min-calls=1,--jit-max-cache=10  system,--jit,--jit-min-calls=1,--jit-max-cache=11  system,--jit,--jit-min-calls=1,--jit-max-cache=12  system,--jit,--jit-min-calls=1,--jit-max-cache=13  system,--jit,--jit-min-calls=1,--jit-max-cache=14  system,--jit,--jit-min-calls=1,--jit-max-cache=15  system,--jit,--jit-min-calls=1,--jit-max-cache=16  system,--jit,--jit-min-calls=1,--jit-max-cache=17  system,--jit,--jit-min-calls=1,--jit-max-cache=18  system,--jit,--jit-min-calls=1,--jit-max-cache=19  system,--jit,--jit-min-calls=1,--jit-max-cache=20  system,--jit,--jit-min-calls=1,--jit-max-cache=21  system,--jit,--jit-min-calls=1,--jit-max-cache=22  system,--jit,--jit-min-calls=1,--jit-max-cache=23  system,--jit,--jit-min-calls=1,--jit-max-cache=24  system,--jit,--jit-min-calls=1,--jit-max-cache=25  system,--jit,--jit-min-calls=1,--jit-max-cache=26  system,--jit,--jit-min-calls=1,--jit-max-cache=27  system,--jit,--jit-min-calls=1,--jit-max-cache=28  system,--jit,--jit-min-calls=1,--jit-max-cache=29  system,--jit,--jit-min-calls=1,--jit-max-cache=30  system,--jit,--jit-min-calls=1,--jit-max-cache=31  system,--jit,--jit-min-calls=1,--jit-max-cache=32 
               bench                                          838.324                                           847.340                                            816.460                                            850.018                                            831.310                                            823.389                                            741.246                                            752.531                                            731.286                                            731.511                                            697.291                                            720.258                                            687.086                                            704.376                                            634.097                                            624.919                                            629.444                                            620.620                                            631.154                                            633.772                                            618.419                                            619.745                                            628.062                                            635.475                                            621.571 i/s -      1.851k times in 2.207978s 2.184482s 2.267106s 2.177600s 2.226607s 2.248025s 2.497146s 2.459701s 2.531156s 2.530380s 2.654560s 2.569913s 2.693987s 2.627858s 2.919113s 2.961984s 2.940690s 2.982500s 2.932725s 2.920609s 2.993115s 2.986710s 2.947160s 2.912781s 2.977937s

Comparison:
                            bench
system,--jit,--jit-min-calls=1,--jit-max-cache=11:       850.0 i/s 
system,--jit,--jit-min-calls=1,--jit-max-cache=9:       847.3 i/s - 1.00x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=8:       838.3 i/s - 1.01x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=12:       831.3 i/s - 1.02x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=13:       823.4 i/s - 1.03x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=10:       816.5 i/s - 1.04x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=15:       752.5 i/s - 1.13x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=14:       741.2 i/s - 1.15x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=17:       731.5 i/s - 1.16x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=16:       731.3 i/s - 1.16x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=19:       720.3 i/s - 1.18x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=21:       704.4 i/s - 1.21x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=18:       697.3 i/s - 1.22x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=20:       687.1 i/s - 1.24x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=31:       635.5 i/s - 1.34x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=22:       634.1 i/s - 1.34x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=27:       633.8 i/s - 1.34x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=26:       631.2 i/s - 1.35x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=24:       629.4 i/s - 1.35x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=30:       628.1 i/s - 1.35x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=23:       624.9 i/s - 1.36x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=32:       621.6 i/s - 1.37x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=25:       620.6 i/s - 1.37x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=29:       619.7 i/s - 1.37x  slower
system,--jit,--jit-min-calls=1,--jit-max-cache=28:       618.4 i/s - 1.37x  slower

1.15 倍くらい遅いグループと 1.35 倍くらい遅いグループと、その中間くらいのあたりにポツポツと見て取れます。 gcc が .so をビルドするのは並列で動いているので、そのビルド時間によって順番が前後することがあり、そのあたりで結果が揺れているのではないかな、と推測しています。 ともあれおおむね、上位 12-23 個のキャッシュの中になにか問題が潜んでいそうだ、ということがわかります。

--jit-verbose

上位 24 個のキャッシュがどういった内容なのか、見てみます。

$ RAILS_ENV=production bundle exec rake bench SIZES="24" JITOPT="--jit-verbose=1" 2>&1|grep "^JIT success"|head -n24
JIT success (167.5ms): _segments@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:376 -> /tmp/_ruby_mjit_p7053u75.c
JIT success (454.1ms): <=>@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:336 -> /tmp/_ruby_mjit_p7053u71.c
JIT success (34.6ms): _version@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:372 -> /tmp/_ruby_mjit_p7053u72.c
JIT success (218.7ms): data@/usr/local/lib/ruby/2.6.0/rubygems/stub_specification.rb:112 -> /tmp/_ruby_mjit_p7053u183.c
JIT success (102.8ms): block in tsort_each_child@/work/foo/.bundle/ruby/2.6.0/gems/railties-5.1.5/lib/rails/initializable.rb:48 -> /tmp/_ruby_mjit_p7053u1475.c
JIT success (39.7ms): before@/work/foo/.bundle/ruby/2.6.0/gems/railties-5.1.5/lib/rails/initializable.rb:17 -> /tmp/_ruby_mjit_p7053u1476.c
JIT success (43.9ms): after@/work/foo/.bundle/ruby/2.6.0/gems/railties-5.1.5/lib/rails/initializable.rb:21 -> /tmp/_ruby_mjit_p7053u1477.c
JIT success (52.4ms): add@/usr/local/lib/ruby/2.6.0/set.rb:348 -> /tmp/_ruby_mjit_p7053u504.c
JIT success (54.2ms): name@/usr/local/lib/ruby/2.6.0/rubygems/stub_specification.rb:159 -> /tmp/_ruby_mjit_p7053u193.c
JIT success (58.5ms): type@/usr/local/lib/ruby/2.6.0/rubygems/dependency.rb:164 -> /tmp/_ruby_mjit_p7053u465.c
JIT success (52.0ms): block (2 levels) in add_downcased_set_members_to_all_set_constants@/work/foo/.bundle/ruby/2.6.0/gems/loofah-2.2.0/lib/loofah/metahelpers.rb:7 -> /tmp/_ruby_mjit_p7053u1243.c
JIT success (208.7ms): requirement@/usr/local/lib/ruby/2.6.0/rubygems/dependency.rb:120 -> /tmp/_ruby_mjit_p7053u173.c
JIT success (57.7ms): get_header@/work/foo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/request.rb:50 -> /tmp/_ruby_mjit_p7053u2907.c
JIT success (961.0ms): []@/work/foo/.bundle/ruby/2.6.0/gems/concurrent-ruby-1.0.5/lib/concurrent/map.rb:92 -> /tmp/_ruby_mjit_p7053u818.c
JIT success (43.5ms): []@/work/foo/.bundle/ruby/2.6.0/gems/concurrent-ruby-1.0.5/lib/concurrent/collection/map/non_concurrent_map_backend.rb:19 -> /tmp/_ruby_mjit_p7053u819.c
JIT success (55.1ms): block in initialize@/work/foo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/ordered_options.rb:71 -> /tmp/_ruby_mjit_p7053u2144.c
JIT success (43.5ms): include?@/usr/local/lib/ruby/2.6.0/set.rb:253 -> /tmp/_ruby_mjit_p7053u614.c
JIT success (74.8ms): block in xor_byte_strings@/work/foo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_controller/metal/request_forgery_protection.rb:388 -> /tmp/_ruby_mjit_p7053u3549.c
JIT success (27.0ms): block (4 levels) in class_attribute@/work/foo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/core_ext/class/attribute.rb:90 -> /tmp/_ruby_mjit_p7053u1040.c
JIT success (125.8ms): instance@/work/foo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/per_thread_registry.rb:44 -> /tmp/_ruby_mjit_p7053u2560.c
JIT success (152.4ms): _segments@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:376 -> /tmp/_ruby_mjit_p7163u75.c
JIT success (414.7ms): <=>@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:336 -> /tmp/_ruby_mjit_p7163u71.c
JIT success (34.9ms): _version@/usr/local/lib/ruby/2.6.0/rubygems/version.rb:372 -> /tmp/_ruby_mjit_p7163u72.c
JIT success (196.5ms): data@/usr/local/lib/ruby/2.6.0/rubygems/stub_specification.rb:112 -> /tmp/_ruby_mjit_p7163u183.c

この中に問題のメソッドがいそうなのですが、さてどうやって絞り込んでいくか、まだ方針が立っていません。

方針見直し

ということをやっていたのですが、どうも見当違いだったようで、https://twitter.com/k0kubun/status/973719115264270337 というコメントをいただきました。

JITableな命令を減らすのは1行でできるようになってて、あとcall cacheを見てopt_系をsendにするのは一応分岐が置いてあります。あとrailsのベンチだと、生成コードを呼び出す代わりにQundef返しても結果がそんな変わらないこともわかっており、k0kubun/ruby#6 でその影響を消せるようです

ということで、Qundef を返すようにパッチを当ててみます。

wanabe@3082ebd775d6:/repo$ (cd /ruby && git stash pop && git diff && cd /work && make -j4 install-nodoc > /dev/null)
On branch trunk
Your branch is up-to-date with 'origin/trunk'.
You are currently bisecting.
  (use "git bisect reset" to get back to the original branch)

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git checkout -- <file>..." to discard changes in working directory)

	modified:   mjit.h

no changes added to commit (use "git add" and/or "git commit -a")
Dropped refs/stash@{0} (a3c4c8c8952c498a0c196a7462aff78c496cc098)
diff --git a/mjit.h b/mjit.h
index c52b253..4d0f534 100644
--- a/mjit.h
+++ b/mjit.h
@@ -123,6 +123,7 @@ mjit_exec(rb_execution_context_t *ec)
         }
     }
 
+    return Qundef;
     return func(ec, ec->cfp);
 }
 
wanabe@3082ebd775d6:/repo$ TEST_COUNT=3000 RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 RUBYOPT='--jit' bundle exec derailed exec perf:test
Booting: production
Endpoint: "/"
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
       user     system      total        real
3000 requests  4.570041   0.078005   9.454855 (  4.643215)

次にパッチなしの状態。

wanabe@3082ebd775d6:/repo$ (cd /ruby && git stash && git diff && cd /work && make -j4 install-nodoc > /dev/null)
Saved working directory and index state WIP on trunk: ec74ad7 Fix test error
HEAD is now at ec74ad7 Fix test error
wanabe@3082ebd775d6:/repo$ TEST_COUNT=3000 RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 RUBYOPT='--jit' bundle exec derailed exec perf:test
Booting: production
Endpoint: "/"
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
       user     system      total        real
3000 requests  4.638926   0.104883   9.325425 (  4.740118)

ということで、

  • JITed なコードの実行によって遅くなっているわけではない
    • 速くならないことはそれはそれで問題だが、別の問題
  • ワーカー、特にその中のビルド、コンパイル処理が問題らしい

ということのようです。

ビルドに時間のかかるケース

全体的なことは後回しにして、まずは個々のメソッドのコンパイル時間を見ていきます。 まず、一つのメソッドやブロックで 500 ms 以上かかるようなパターンを抽出します。

wanabe@9e1705c6654f:/repo$ RAILS_ENV=production bundle exec rake bench BENCH_CONFIG='run_duration=20' JIT_OPTS="verbose=2,save-temps" 2>&1|grep "JIT success (\([0-9]\{4,\}\|[5-9][0-9]\{2,\}\)\.[0-9]ms"
JIT success (1025.4ms): []@/repo/.bundle/ruby/2.6.0/gems/concurrent-ruby-1.0.5/lib/concurrent/map.rb:92 -> /tmp/_ruby_mjit_p2992u429.c
JIT success (949.2ms): []=@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/utils.rb:468 -> /tmp/_ruby_mjit_p2992u1181.c
JIT success (894.9ms): initialize@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/core_ext/string/output_safety.rb:173 -> /tmp/_ruby_mjit_p2992u1154.c
JIT success (1033.6ms): respond_to?@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/body_proxy.rb:9 -> /tmp/_ruby_mjit_p2992u1192.c
JIT success (1011.5ms): initialize@/repo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_dispatch/http/request.rb:56 -> /tmp/_ruby_mjit_p2992u1075.c
JIT success (1093.7ms): initialize@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/request.rb:38 -> /tmp/_ruby_mjit_p2992u1076.c
JIT success (1011.2ms): initialize@/repo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_dispatch/http/url.rb:187 -> /tmp/_ruby_mjit_p2992u1077.c
JIT success (954.5ms): []@/repo/.bundle/ruby/2.6.0/gems/concurrent-ruby-1.0.5/lib/concurrent/map.rb:92 -> /tmp/_ruby_mjit_p3217u429.c
JIT success (976.4ms): []=@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/utils.rb:468 -> /tmp/_ruby_mjit_p3217u1181.c
JIT success (875.3ms): initialize@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/core_ext/string/output_safety.rb:173 -> /tmp/_ruby_mjit_p3217u1154.c
JIT success (971.0ms): respond_to?@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/body_proxy.rb:9 -> /tmp/_ruby_mjit_p3217u1192.c
JIT success (970.0ms): initialize@/repo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_dispatch/http/request.rb:56 -> /tmp/_ruby_mjit_p3217u1075.c
JIT success (893.4ms): initialize@/repo/.bundle/ruby/2.6.0/gems/rack-2.0.4/lib/rack/request.rb:38 -> /tmp/_ruby_mjit_p3217u1076.c
JIT success (857.2ms): initialize@/repo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_dispatch/http/url.rb:187 -> /tmp/_ruby_mjit_p3217u1077.c
JIT success (850.7ms): initialize@/repo/.bundle/ruby/2.6.0/gems/actionpack-5.1.5/lib/action_dispatch/http/filter_parameters.rb:32 -> /tmp/_ruby_mjit_p3217u1078.c
JIT success (928.0ms): update@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/hash_with_indifferent_access.rb:121 -> /tmp/_ruby_mjit_p3217u1089.c
JIT success (856.4ms): default@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/hash_with_indifferent_access.rb:204 -> /tmp/_ruby_mjit_p3217u1156.c
JIT success (834.4ms): level@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/logger_thread_safe_level.rb:27 -> /tmp/_ruby_mjit_p3217u1140.c
JIT success (989.6ms): initialize@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/hash_with_indifferent_access.rb:64 -> /tmp/_ruby_mjit_p3217u1093.c

（自分で扱いやすいように rake タスクをごにょごにょしているのでコマンドの意味はよくわからないかもしれません。 　タスクの中身は本筋ではないので、字面でなんとなく理解する程度でいいと思います）

先頭の .bundle/ruby/2.6.0/gems/concurrent-ruby-1.0.5/lib/concurrent/map.rb:92 -> /tmp/_ruby_mjit_p2992u429.c というやつを手元にコピーして、ビルドしてみます。

wanabe@9e1705c6654f:/repo$ cp /tmp/_ruby_mjit_p2992u429.c a.c
wanabe@9e1705c6654f:/repo$ time gcc -shared -Wfatal-errors -fPIC -shared -w -pipe -O3 -o a.so a.c -Wl,--compress-debug-sections=zlib -nostartfiles -nodefaultlibs -nostdlib

real	0m0.917s
user	0m0.911s
sys	0m0.026s

なるほどこれは時間がかかっている。どこに時間がかかっているか、手動 bisect で探してみます。

手動 bisect とは

特に専門用語とかではありません。今適当に作りました。 二分木探索で問題のある箇所を探すという程度の意味で使っています。 今やろうとしているのは、

wanabe@9e1705c6654f:/repo$ grep ^label a.c|wc -l
34

これを

wanabe@9e1705c6654f:/repo$ cat a.c|ruby -pe 'range = 1..34; $c ||= 0; label = false; if /^label/ =~ $prev; $c += 1; label = true; end; if range === $c; if label; $_ = "#if 0\n#{$_}"; elsif /^}$/ =~ $_; $_ << "#endif\n"; end; end; $prev = $_ ' > b.c

$ time gcc -shared -Wfatal-errors -fPIC -shared -w -pipe -O3 -o b.so b.c -Wl,--compress-debug-sections=zlib -nostartfiles -nodefaultlibs -nostdlib

real	0m0.054s
user	0m0.030s
sys	0m0.034s

こんな感じで、部分ごとに #if 0 ... #endif で囲んでコードを小さい状態にしてから、徐々に元の状態に近づけていくとどこでビルド時間が変化するかを見ていこうということです。 これで確認すると、最終的に

$ cat a.c|ruby -pe 'range = 3..3; $c ||= 0; label = false; if /^label/ =~ $prev; $c += 1; label = true; end; if range === $c; if label; $_ = "#if 0\n#{$_}"; elsif /^}$/ =~ $_; $_ << "#endif\n"; end; end; $prev = $_ ' > b.c; time gcc -shared -Wfatal-errors -fPIC -shared -w -pipe -O3 -o b.so b.c -Wl,--compress-debug-sections=zlib -nostartfiles -nodefaultlibs -nostdlib

real	0m0.138s
user	0m0.124s
sys	0m0.018s

$ sed -ne $((`sed -n '/#if 0/=' b.c`- 1))',/#endif/p' b.c
label_4: /* invokesuper */
#if 0
{
    MAYBE_UNUSED(unsigned int) stack_size = 2;
    MAYBE_UNUSED(CALL_CACHE) cc;
    MAYBE_UNUSED(CALL_INFO) ci;
    MAYBE_UNUSED(ISEQ) blockiseq;
    MAYBE_UNUSED(VALUE) val;
    ci = (CALL_INFO)0x5593f4646ce0;
    cc = (CALL_CACHE)0x5593f4645720;
    blockiseq = (ISEQ)0x0;
    reg_cfp->sp = (VALUE *)reg_cfp->bp + stack_size + 1 - 0;
    *(reg_cfp->sp + -2) = stack[0];
    *(reg_cfp->sp + -1) = stack[1];
    {
        struct rb_calling_info calling;
        calling.argc = ci->orig_argc;

        vm_caller_setup_arg_block(ec, reg_cfp, &calling, ci, blockiseq, TRUE);
        calling.recv = GET_SELF();
        vm_search_super_method(ec, GET_CFP(), &calling, ci, cc);
        CALL_METHOD(&calling, ci, cc);
    }
    stack[0] = val;
    if (UNLIKELY(ruby_vm_event_enabled_flags & ISEQ_TRACE_EVENTS)) {
        reg_cfp->sp = (VALUE *)reg_cfp->bp + 2;
        reg_cfp->pc = original_body_iseq + 8;
        goto cancel;
    }
}
#endif

invokesuper が入ると極端に遅くなる、ということがわかりました。 ということはおそらく vm_search_super_method() が悪いのでしょう。

既視感

そういえば以前似たようなことがあった気がします。 のでログを漁りましたところ、https://github.com/k0kubun/yarv-mjit/commit/7a1cfe6c9f5d80b134463c9693d0eda4a47edd4d とか https://github.com/k0kubun/yarv-mjit/commit/ee265e8d0ad40344982753b498be72362f9cb5e0 なんかがそれっぽいです。 よくわからないけれども tool/transform_mjit_header.rb の IGNORED_FUNCTIONS に vm_search_super_method() を追加してみます。 ignore するということはヘッダに含めなくなるわけで ruby の中の関数を呼び出すことになるわけで、static ではいけません。 ということでパッチはこんな感じになりました。

diff --git a/mjit.h b/mjit.h
index c52b253c04..4d0f534d15 100644
--- a/mjit.h
+++ b/mjit.h
@@ -123,6 +123,7 @@ mjit_exec(rb_execution_context_t *ec)
         }
     }
 
+    return Qundef;
     return func(ec, ec->cfp);
 }
 
diff --git a/tool/transform_mjit_header.rb b/tool/transform_mjit_header.rb
index f53f1252cb..165a8c9b34 100644
--- a/tool/transform_mjit_header.rb
+++ b/tool/transform_mjit_header.rb
@@ -33,6 +33,7 @@ module MJITHeader
 
   IGNORED_FUNCTIONS = [
     'vm_search_method_slowpath', # This increases the time to compile when inlined. So we use it as external function.
+    'vm_search_super_method', # ditto
     'rb_equal_opt', # Not used from VM and not compilable
   ]
 
diff --git a/vm_insnhelper.c b/vm_insnhelper.c
index 0f365db3f5..8087625425 100644
--- a/vm_insnhelper.c
+++ b/vm_insnhelper.c
@@ -2460,7 +2460,7 @@ vm_super_outside(void)
     rb_raise(rb_eNoMethodError, "super called outside of method");
 }
 
-static void
+MJIT_FUNC_EXPORTED void
 vm_search_super_method(const rb_execution_context_t *ec, rb_control_frame_t *reg_cfp,
                       struct rb_calling_info *calling, struct rb_call_info *ci, struct rb_call_cache *cc)
 {

この状態でもう一度 500 ms 以上ビルドにかかるものを確認し、また最初のベンチマークも確認します。

wanabe@9e1705c6654f:/repo$ RAILS_ENV=production bundle exec rake bench BENCH_CONFIG='run_duration=20' JIT_OPTS="verbose=2,save-temps" 2>&1|grep "JIT success (\([0-9]\{4,\}\|[5-9][0-9]\{2,\}\)\.[0-9]ms"
JIT success (584.0ms): instrument@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/notifications.rb:164 -> /tmp/_ruby_mjit_p4871u760.c
JIT success (660.7ms): cache@/repo/.bundle/ruby/2.6.0/gems/actionview-5.1.5/lib/action_view/template/resolver.rb:63 -> /tmp/_ruby_mjit_p5326u1132.c
JIT success (597.5ms): run_callbacks@/repo/.bundle/ruby/2.6.0/gems/activesupport-5.1.5/lib/active_support/callbacks.rb:93 -> /tmp/_ruby_mjit_p5326u1195.c

wanabe@9e1705c6654f:/repo$ (cd /repo; TEST_COUNT=3000 RAILS_ENV=production RAILS_SERVE_STATIC_FILES=1 RAILS_LOG_TO_STDOUT=1 RUBYOPT='--jit' bundle exec derailed exec perf:test)
Booting: production
Endpoint: "/"
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:86: warning: already initialized constant DERAILED_APP
/repo/.bundle/ruby/2.6.0/gems/derailed_benchmarks-1.3.4/lib/derailed_benchmarks/tasks.rb:23: warning: previous definition of DERAILED_APP was here
       user     system      total        real
3000 requests  4.836079   0.065551   9.948932 (  4.889255)

ビルド時間の軽減には成功しましたが、ベンチマークはやはり改善しません。残念。

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment