Bug #11559
closedビジーループの thread と YAML.parse を組み合わせたときの実行時間が 2.2.3 で遅くなっている
Added by takkanm (三村 益隆) about 9 years ago. Updated about 9 years ago.
Description
ビジーループするスレッドと 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
Updated by hsbt (Hiroshi SHIBATA) about 9 years ago
YAML の psych は 2.2.3 で変わっていないので Ruby 本体の Thread まわりのなにかだと思います。
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
一報、スレッドのほうはというと Bug #11030 だけなので、見るからに関係なさそう
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
- 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 の2つを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
Updated by nagachika (Tomoyuki Chikanaga) about 9 years ago
報告&調査ありがとうございます。
fifo を(というか長時間 block しうる fd から) load するというあまりなさそうなケースのために、顕著なパフォーマンスの悪化を伴なうのはよくないと思いますので、branch での revert に同意します。
2.1 での方針と、つまり usa さんの判断とを待って実際の revert は作業したいと思います。
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
- 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.
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
- Status changed from Closed to Open
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
- Related to Bug #11060: load(fifo) blocks whole process added
Updated by nobu (Nobuyoshi Nakada) about 9 years ago
ベンチマークを取ってみたのですが、どうもそれだけではないように思えます。
-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 |
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
ベンチマークを取ってみたのですが、どうもそれだけではないように思えます。
-gvl
と付いているのがr50887をrevertしたバージョンです。
これ、何回測定した平均でしょうか。require_threadはブレが非常に大きいので
試行回数を多くする必要があります。ベストケースでは2.2.3でもほぼ性能劣化しません
Updated by nobu (Nobuyoshi Nakada) about 9 years ago
数回程度ですが、ratioを見ると大体同じくらいの数値です。
気になっているのはベストケースではなく r50887 をrevertしても2.2.2よりもかなり遅いままという点です。
Updated by nobu (Nobuyoshi Nakada) about 9 years ago
- 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.
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
調査してみたところ、今回のケースでは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倍以上遅い現象は、こちらでは一度も再現できていないことは付記しておきます。
Updated by kosaki (Motohiro KOSAKI) about 9 years ago
せっかくなので、 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
なので、悪くない数値だと思います。
Updated by nobu (Nobuyoshi Nakada) over 5 years ago
- Related to Bug #15787: LoadError by EPERM on read-only volume added
Updated by nobu (Nobuyoshi Nakada) over 5 years ago
- Related to deleted (Bug #15787: LoadError by EPERM on read-only volume)