Bug #3443: requireが遅くなる

• Status: Closed
• Assignee: mame (Yusuke Endoh)
• Target version: 1.9.2
• ruby -v: ruby 1.9.3dev (2010-05-30 trunk 28086) [i386-cygwin]

[mame (Yusuke Endoh)]

=begin
[ruby-dev:41502] をチケット化します。

---

三浦と申します。

1年ぶりくらいに最新バージョンのRubyでyarv2llvmを動かしてみたら、
すごく時間がかかるようになっていたので調べてみました。
環境は以下の通りです。
　　CPU AMD Athlon(tm)X2 Dual-Core QL-60 1.90 GHz

　RAM 4GBytes

 OS    Windows Vista

CYGWIN_NT-6.0 miura-PC 1.7.5(0.225/5/3) 2010-04-12 19:07 i686 Cygwin

Ruby ruby 1.9.3dev (2010-05-30 trunk 28086) [i386-cygwin]

その結果、require時にファイル入力の後に大量のRead/Writeではない
File Operationが発生していることが分かりました。
さらに、strace(Cygwin版)を見たところ、次のようなシステムコールが
大量に発生していました。

857 67985110 [main] ruby 4896 open: open
(/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb, 0x0)
101 67985211 [main] ruby 4896 normalize_posix_path: src
/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb
96 67985307 [main] ruby 4896 normalize_posix_path:
/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb =
normalize_posix_path
(/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb)
96 67985403 [main] ruby 4896 mount_info::conv_to_win32_path:
conv_to_win32_path
(/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb)
96 67985499 [main] ruby 4896 set_flags: flags: binary (0x2)
90 67985589 [main] ruby 4896 mount_info::conv_to_win32_path: src_path
/home/miura/demo/yarv2llvm64/yarv2llvm/lib/vmtraverse.rb, dst
C:\cygwin\home\miura\demo\yarv2llvm64\yarv2llvm\lib\vmtraverse.rb, flags
0x3000A, rc 0
954 67986543 [main] ruby 4896 symlink_info::check: 0x0 = NtCreateFile
(??\C:\cygwin\home\miura\demo\yarv2llvm64\yarv2llvm\lib\vmtraverse.rb)
352 67986895 [main] ruby 4896 symlink_info::check: not a symlink
575 67987470 [main] ruby 4896 symlink_info::check: 0 = symlink.check
(C:\cygwin\home\miura\demo\yarv2llvm64\yarv2llvm\lib\vmtraverse.rb,
0x22A320) (0x3000A)
156 67987626 [main] ruby 4896 path_conv::check:
this->path(C:\cygwin\home\miura\demo\yarv2llvm64\yarv2llvm\lib\vmtraverse.rb),
has_acls(1)
144 67987770 [main] ruby 4896 build_fh_pc: fh 0x612269D4
103 67987873 [main] ruby 4896 fhandler_base::open:
(??\C:\cygwin\home\miura\demo\yarv2llvm64\yarv2llvm\lib\vmtraverse.rb,
0x100000)
711 67988584 [main] ruby 4896 fhandler_base::set_flags: flags 0x100000,
supplied_bin 0x10000

これを見る限り、Cygwinではファイルのパスを得るために
ファイルシステムのアクセスを含む結構重い処理を行っているようです。

そこで、ファイルパスを繰り返し得る処理をしているところを
探したところ、iseq.cのprepare_iseq_build中の

iseq->filepath = filepath == Qnil ? Qnil : rb_realpath_internal(Qnil,
filepath, 1);

が見つかりました。試しにiseq->filepathを常にQnilにするように変更
して、実行速度の差を見てみました。

結果です。
time ruby -I . yarv2llvm.rb fib.rb

オリジナル
real 0m35.954s
user 0m4.163s
sys 0m14.351s

常にQnil　　　　　　　
real 0m10.323s
user 0m2.525s
sys 0m3.197s

また、rb_realpath_internal(Qnil, filepath, 1)の結果をキャッシュする
ようにしてみました。その結果です。

キャッシュ
real 0m26.757s
user 0m3.291s
sys 0m10.623s

この実験で使った変更点を以下に示します。
なお、iseq_s_compileの

• rb_scan_args(argc, argv, "13", &src, &file, &path, &line, &opt);

• rb_scan_args(argc, argv, "14", &src, &file, &path, &line, &opt);
  は直接関係ないのですが、ついでに乗せておきます。
  こちらも御検討してもらえると幸いです。

Index: iseq.c

--- iseq.c (revision 28086)
+++ iseq.c (working copy)
@@ -217,7 +217,22 @@

VALUE rb_realpath_internal(VALUE basedir, VALUE path, int strict);

+static VALUE path_cache;
+static VALUE realpath_cache;
static VALUE
+realpath_iseq(VALUE path)
+{

• if (path_cache == path) {

•    return realpath_cache;
  

• }
• path_cache = path;
• realpath_cache = rb_realpath_internal(Qnil, path, 1);
• return realpath_cache;
  +}

+static VALUE
prepare_iseq_build(rb_iseq_t *iseq,
VALUE name, VALUE filename, VALUE filepath, VALUE line_no,
VALUE parent, VALUE type, VALUE block_opt,
@@ -228,7 +243,9 @@

  iseq->name = name;
  iseq->filename = filename;

• iseq->filepath = filepath == Qnil ? Qnil : rb_realpath_internal(Qnil,
  filepath, 1);

• //iseq->filepath = filepath == Qnil ? Qnil : rb_realpath_internal(Qnil,
  filepath, 1);

• iseq->filepath = filepath == Qnil ? Qnil : realpath_iseq(filepath);

• // iseq->filepath = Qnil;
  iseq->line_no = (unsigned short)line_no; /* TODO: really enough? */
  iseq->defined_method_id = 0;
  iseq->mark_ary = rb_ary_tmp_new(3);
  @@ -579,7 +596,7 @@

  rb_secure(1);

• rb_scan_args(argc, argv, "13", &src, &file, &path, &line, &opt);

• rb_scan_args(argc, argv, "14", &src, &file, &path, &line, &opt);
  if (NIL_P(file)) file = rb_str_new2("");
  if (NIL_P(line)) line = INT2FIX(1);

@@ -1516,5 +1533,7 @@
rb_define_singleton_method(rb_cISeq, "compile_option=",
iseq_s_compile_option_set, 1);
rb_define_singleton_method(rb_cISeq, "disasm", iseq_s_disasm, 1);
rb_define_singleton_method(rb_cISeq, "disassemble", iseq_s_disasm, 1);
+

• rb_global_variable(&path_cache);
  }
  =end

[mame (Yusuke Endoh)]

• Category set to core
• Assignee set to mame (Yusuke Endoh)

=begin
遠藤です。

prepare_iseq_build の中で expand_path するのは確かに遅そうなので、
rb_iseq_new を呼ぶ側でそれぞれ expand_path するようなパッチを書いて
みました。
三浦さんから効果が確認してもらったらコミットしようと思います。

diff --git a/eval_intern.h b/eval_intern.h
index 909b10a..549953a 100644
--- a/eval_intern.h
+++ b/eval_intern.h
@@ -205,7 +205,7 @@ NORETURN(void rb_raise_method_missing(rb_thread_t *th, int argc, VALUE *argv,

VALUE rb_vm_make_jump_tag_but_local_jump(int state, VALUE val);
NODE *rb_vm_cref(void);
-VALUE rb_vm_call_cfunc(VALUE recv, VALUE (*func)(VALUE), VALUE arg, const rb_block_t *blockptr, VALUE filename, VALUE filepath);
+VALUE rb_vm_call_cfunc(VALUE recv, VALUE (*func)(VALUE), VALUE arg, const rb_block_t *blockptr, VALUE filename);
void rb_vm_set_progname(VALUE filename);
void rb_thread_terminate_all(void);
VALUE rb_vm_top_self();
diff --git a/iseq.c b/iseq.c
index 48d0cdf..ae45884 100644
--- a/iseq.c
+++ b/iseq.c
@@ -228,7 +228,7 @@ prepare_iseq_build(rb_iseq_t *iseq,

  iseq->name = name;
  iseq->filename = filename;

• iseq->filepath = filepath == Qnil ? Qnil : rb_realpath_internal(Qnil, filepath, 1);

• iseq->filepath = filepath;
  iseq->line_no = (unsigned short)line_no; /* TODO: really enough? */
  iseq->defined_method_id = 0;
  iseq->mark_ary = rb_ary_tmp_new(3);
  @@ -606,7 +606,8 @@ iseq_s_compile_file(int argc, VALUE *argv, VALUE self)
  parser = rb_parser_new();
  node = rb_parser_compile_file(parser, fname, f, NUM2INT(line));
  make_compile_option(&option, opt);

• return rb_iseq_new_with_opt(node, rb_str_new2(""), file, file, line, Qfalse,

• return rb_iseq_new_with_opt(node, rb_str_new2(""), file,

•  		rb_realpath_internal(Qnil, file, 1), line, Qfalse,
   		ISEQ_TYPE_TOP, &option);
  

}

diff --git a/load.c b/load.c
index b4ec2d9..a0e5a4b 100644
--- a/load.c
+++ b/load.c
@@ -297,7 +297,7 @@ rb_load_internal(VALUE fname, int wrap)
th->mild_compile_error++;
node = (NODE *)rb_load_file(RSTRING_PTR(fname));
loaded = TRUE;

• iseq = rb_iseq_new_top(node, rb_str_new2("<top (required)>"), fname, fname, Qfalse);

• iseq = rb_iseq_new_top(node, rb_str_new2("<top (required)>"), fname, rb_realpath_internal(Qnil, fname, 1), Qfalse);
  th->mild_compile_error--;
  rb_iseq_eval(iseq);
  }
  @@ -596,7 +596,7 @@ rb_require_safe(VALUE fname, int safe)

    case 's':
      handle = (long)rb_vm_call_cfunc(rb_vm_top_self(), load_ext,
  

•  				    path, 0, path, path);
  

•  				    path, 0, path);
       rb_ary_push(ruby_dln_librefs, LONG2NUM(handle));
       break;
   }
  

@@ -643,7 +643,7 @@ ruby_init_ext(const char *name, void (*init)(void))
{
if (load_lock(name)) {
rb_vm_call_cfunc(rb_vm_top_self(), init_ext_call, (VALUE)init,

•  	 0, rb_str_new2(name), Qnil);
  

•  	 0, rb_str_new2(name));
  

  rb_provide(name);
  load_unlock(name, 1);
  }
  diff --git a/ruby.c b/ruby.c
  index daaf0d6..75ea88f 100644
  --- a/ruby.c
  +++ b/ruby.c
  @@ -1462,7 +1462,8 @@ process_options(int argc, char **argv, struct cmdline_options *opt)

  PREPARE_PARSE_MAIN({
  VALUE path = Qnil;

• if (!opt->e_script && strcmp(opt->script, "-")) path = opt->script_name;

• if (!opt->e_script && strcmp(opt->script, "-"))

•  path = rb_realpath_internal(Qnil, opt->script_name, 1);
  

  iseq = rb_iseq_new_main(tree, opt->script_name, path);
  });

diff --git a/vm.c b/vm.c
index bc11094..3516024 100644
--- a/vm.c
+++ b/vm.c
@@ -1450,11 +1450,11 @@ rb_thread_current_status(const rb_thread_t *th)

VALUE
rb_vm_call_cfunc(VALUE recv, VALUE (*func)(VALUE), VALUE arg,

•   const rb_block_t *blockptr, VALUE filename, VALUE filepath)
  

•   const rb_block_t *blockptr, VALUE filename)
  

{
rb_thread_t *th = GET_THREAD();
const rb_control_frame_t *reg_cfp = th->cfp;

• volatile VALUE iseqval = rb_iseq_new(0, filename, filename, filepath, 0, ISEQ_TYPE_TOP);

• volatile VALUE iseqval = rb_iseq_new(0, filename, filename, Qnil, 0, ISEQ_TYPE_TOP);
  VALUE val;

  vm_push_frame(th, DATA_PTR(iseqval), VM_FRAME_MAGIC_TOP,

--
Yusuke Endoh [e-mail]
=end

=begin
三浦です

パッチありがとうございます。効果を確認しました。

チケット #3443 が更新されました。 (by Yusuke Endoh)

カテゴリ coreにセット
担当者 Yusuke Endohにセット

遠藤です。

prepare_iseq_build の中で expand_path するのは確かに遅そうなので、
rb_iseq_new を呼ぶ側でそれぞれ expand_path するようなパッチを書いて
みました。
三浦さんから効果が確認してもらったらコミットしようと思います。

結果、3倍以上の速度向上でした。
yarv2llvmでfibをコンパイルして実行する時間を測定しました。3回測定して
一番成績の良いものを載せています。

Rubyのバージョン
$ ruby -v
ruby 1.9.3dev (2010-06-16 trunk 28332) [i386-cygwin]

パッチ前

$ time ruby -I . -I lib/ yarv2llvm.rb fib.rb
102334155

real 0m34.876s
user 0m4.102s
sys 0m14.476s

パッチ後

$ time ruby -I . -I lib/ yarv2llvm.rb fib.rb
102334155

real 0m9.816s
user 0m2.760s
sys 0m3.462s

=end

[mame (Yusuke Endoh)]

• Status changed from Open to Closed
• % Done changed from 0 to 100

=begin
This issue was solved with changeset r28351.
Yusuke, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.

=end