Project

General

Profile

Bug #11559

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

Added by takkanm (三村 益隆) over 4 years ago. Updated over 4 years ago.

Status:
Closed
Priority:
Normal
Target version:
-
[ruby-dev:<unknown>]

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

Related issues

Related to Ruby master - Bug #11060: load(fifo) blocks whole processClosedActions
#1

Updated by hsbt (Hiroshi SHIBATA) over 4 years ago

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

#2

Updated by kosaki (Motohiro KOSAKI) over 4 years ago

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

#3

Updated by kosaki (Motohiro KOSAKI) over 4 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

#4

Updated by nagachika (Tomoyuki Chikanaga) over 4 years ago

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

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

#5

Updated by kosaki (Motohiro KOSAKI) over 4 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.
#6

Updated by kosaki (Motohiro KOSAKI) over 4 years ago

  • Status changed from Closed to Open
#7

Updated by kosaki (Motohiro KOSAKI) over 4 years ago

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

Updated by nobu (Nobuyoshi Nakada) over 4 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) over 4 years ago

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

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

Updated by nobu (Nobuyoshi Nakada) over 4 years ago

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

#11

Updated by nobu (Nobuyoshi Nakada) over 4 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) over 4 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) over 4 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

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

#14

Updated by nobu (Nobuyoshi Nakada) about 1 year ago

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

Updated by nobu (Nobuyoshi Nakada) about 1 year ago

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

Also available in: Atom PDF