Bug #11559: ビジーループの thread と YAML.parse を組み合わせたときの実行時間が 2.2.3 で遅くなっている

• Status: Closed
• Assignee: nobu (Nobuyoshi Nakada)
• Target version: -
• ruby -v: 2.2.3
• Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN, 2.2: UNKNOWN

[takkanm (三村 益隆)]

ビジーループするスレッドと YAML.parse を並行して実行するような以下のようなコードが 2.2.2 と 2.2.3 で、
数倍遅くなっているようです。trunk でも遅いことを確認してます。

require 'thread'
require 'yaml'

puts RUBY_VERSION

y = (1..1000).to_a.to_yaml
t = Thread.new do
  while true; 1;end
end

10.times do
  YAML.load(y)
end

t.kill

実行結果

$ time ruby thread_loop_with_while.rb 
2.2.2
ruby thread_loop_with_while.rb  0.30s user 0.06s system 94% cpu 0.375 total

$ time ruby thread_loop_with_loop.rb
2.2.3
ruby thread_loop_with_loop.rb  1.80s user 0.05s system 99% cpu 1.864 total

[hsbt (Hiroshi SHIBATA)]

YAML の psych は 2.2.3 で変わっていないので Ruby 本体の Thread まわりのなにかだと思います。

[kosaki (Motohiro KOSAKI)]

一報、スレッドのほうはというと Bug #11030 だけなので、見るからに関係なさそう

[kosaki (Motohiro KOSAKI)]

• Status changed from Open to Assigned
• Assignee set to nobu (Nobuyoshi Nakada)

エスパー能力により r50887 [Bug #11060] だと分かりました。
ためしにprintf入れてみたところ、yaml.loadの延長で結構な数の loadopen_func 処理（メッセージ末尾に貼ります）が走っており、
それが毎回GVL switchをするようになったので、なにもしてないスレッドにたくさん時間が渡る結果になったようです。

で、根本原因はといいますと、utf_16le, utf_16be の２つをloadしたいだけなのに、pathの都合で、16回ほどGVLを取ったり
話したりしてるわけですよ。つまり require自体が全体的に遅くなってる。

r50887 は stable branch では一旦revert, [Bug #11060] は reopenのうえ、trunkで再修正を動議します。

---

/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/2.3.0/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/2.3.0/x86_64-linux/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/2.3.0/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/2.3.0/x86_64-linux/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/2.3.0/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/2.3.0/x86_64-linux/enc/utf_16le.so
/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/2.3.0/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/2.3.0/x86_64-linux/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/site_ruby/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/2.3.0/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/2.3.0/x86_64-linux/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/vendor_ruby/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/2.3.0/enc/utf_16be.so
/home/kosaki/local/ruby-trunk/lib/ruby/2.3.0/x86_64-linux/enc/utf_16be.so

[nagachika (Tomoyuki Chikanaga)]

報告&調査ありがとうございます。

fifo を(というか長時間 block しうる fd から) load するというあまりなさそうなケースのために、顕著なパフォーマンスの悪化を伴なうのはよくないと思いますので、branch での revert に同意します。
2.1 での方針と、つまり usa さんの判断とを待って実際の revert は作業したいと思います。

[kosaki (Motohiro KOSAKI)]

• Status changed from Assigned to Closed

Applied in changeset r52083.

---

• benchmark/bm_require.rb: new benchmark for require.
• benchmark/bm_require_thread.rb: new benchmark for conflicting
  require vs thread. like [Bug #11559]
• prepare_require.rb: new file for preparing above tests.
• prepare_require.rb: ditto.

[kosaki (Motohiro KOSAKI)]

• Status changed from Closed to Open

[kosaki (Motohiro KOSAKI)]

• Related to Bug #11060: load(fifo) blocks whole process added

[nobu (Nobuyoshi Nakada)]

ベンチマークを取ってみたのですが、どうもそれだけではないように思えます。
-gvlと付いているのが r50887 をrevertしたバージョンです。

---

benchmark results:
Execution time (sec)

name	2.2.0	2.2.2	2.2.3	2.2.3-gvl	r52118	trunk-gvl
require	3.332	3.380	3.679	1.975	1.279	1.212
require_thread	1.289	1.671	100.325	18.569	21.528	16.998

Speedup ratio: compare with the result of `2.2.0' (greater is better)

name	2.2.2	2.2.3	2.2.3-gvl	r52118	trunk-gvl
require	0.986	0.906	1.687	2.606	2.750
require_thread	0.772	0.013	0.069	0.060	0.076

[kosaki (Motohiro KOSAKI)]

ベンチマークを取ってみたのですが、どうもそれだけではないように思えます。
-gvlと付いているのがr50887をrevertしたバージョンです。

これ、何回測定した平均でしょうか。require_threadはブレが非常に大きいので
試行回数を多くする必要があります。ベストケースでは2.2.3でもほぼ性能劣化しません

[nobu (Nobuyoshi Nakada)]

数回程度ですが、ratioを見ると大体同じくらいの数値です。
気になっているのはベストケースではなく r50887 をrevertしても2.2.2よりもかなり遅いままという点です。

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Closed

Applied in changeset r52139.

---

file.c: non-blocking open

• file.c (rb_file_load_ok): open in non-blocking mode withoout
  releasing GVL. don't care about others than regular files and
  directories. [ruby-dev:49272] [Bug #11559]
• ruby.c (load_file_internal): ditto.

[kosaki (Motohiro KOSAKI)]

調査してみたところ、今回のケースではGVLの所有権変更はすべてIO.closeを契機に行われており、
要するにopenの回数が変わっているのですが、それはなにかというと did_you_mean.
gem_prelude.rbから require 'did_you_mean' を削除してみたところ、以下のように性能劣化が
なくなりました。

ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.527653928
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.426449087
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 2.638254863
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.828310768
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.625604287
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.525134804
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.324337379
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.231783409
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 2.652402031
ruby 2.0.0p598 (2014-11-13) [x86_64-linux] 1.120792229
built-ruby 1.939639205
built-ruby 2.936679158
built-ruby 2.339801367
built-ruby 1.252506794
built-ruby 2.64641999
built-ruby 0.936793636
built-ruby 3.960754206
built-ruby 2.346939978
built-ruby 0.636585395
built-ruby 0.957402811
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 2.668524054
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 3.179867816
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 0.95098083
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.566350784
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.864899405
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.357870921
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.865036693
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.780426887
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 2.162654032
ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux] 1.560896831

name ruby 2.0.0p598 (2014-11-13) [x86_64-linux] built-ruby ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]
require_thread 1.121 0.637 0.951

Speedup ratio: compare with the result of `ruby 2.0.0p598 (2014-11-13) [x86_64-linux]' (greater is better)
name built-ruby ruby 2.2.2p95 (2015-04-13 revision 50295) [x86_64-linux]
require_thread 1.761 1.179

ただし、中田さんが指摘している 2.2.2とくらべてtrunkが10倍以上遅い現象は、こちらでは一度も再現できていないことは付記しておきます。

[kosaki (Motohiro KOSAKI)]

せっかくなので、 did_you_meanが入っても 2.2.0より早くなるよう、r52152で高速化パッチを入れました。Rubyではrequireの速度が超重要であることが経験的に分かっているので、IO.close処理にそれ用の最適化を入れてみました。

$ make benchmark OPTS="-r 10 -p bm_require_t -e ruby-trunk -e ruby-2.2.2"
build-ruby: 0.171
ruby 2.3.0dev(r52151): 0.659
ruby 2.2.0p95 (r50295): 0.834

なので、悪くない数値だと思います。

[nobu (Nobuyoshi Nakada)]

• Related to Bug #15787: LoadError by EPERM on read-only volume added

[nobu (Nobuyoshi Nakada)]

• Related to deleted (Bug #15787: LoadError by EPERM on read-only volume)