[ruby-dev:41471] Re: NoMethodErrorなどのmessage

咳といいます。

まつもとさん、お返事ありがとうございます。

On 2010/05/30, at 15:19, Yukihiro Matsumoto wrote:

> まつもと ゆきひろです
> 
> In message "Re: [ruby-dev:41329] NoMethodErrorなどのmessage"
>    on Sun, 16 May 2010 23:06:00 +0900, Masatoshi SEKI <[e-mail]> writes:
> 
> |ちょっと前からRWikiというWiki風のアプリケーションを
> |書いています。
> |たくさんのオブジェクトを参照しているRWikiのオブジェクトに、
> |irbで対話的にメッセージを送ることがよくあるのですが、
> |その際にメソッド名を間違えるととても長い時間待たされて
> |困っています。
> 
> もうちょっと状況を説明してください。
> 
> まず、inspectを避けるかどうかを考える前に、NameError系はまさ
> にこのような「とても長い」処理を避けるために、to_strを遅延し
> ています。例外を印字しようとするなど明示的に要求しない限り、
> to_strを呼ばないはずです。ということは、本来
> 
> |この関数はMarshalの際にも呼ばれるようで、dRubyで例外が
> |あがる際にもエラーを印字しない場合にも長い時間がかかります。
> 
> のように「印字しない場合にも呼ばれる」ということは起きないは
> ずです。にもかかわらず、長い時間がかかると言うのは、dRubyが無
> 駄にmessageを取り出しているのではないでしょうか。でなければ、
> バグです。まずはここから考えたいです。
> 
> あと、「とても長い」も興味深い点です。これは1回1回の時間はさ
> ほどでもないが、繰り返すので蓄積されて結果的に「とても長い」
> のでしょうか、それともdRubyの性質上、inspectが内部で呼び出す
> to_sなどがネットワークを越えるので、「とても長い」のでしょう
> か。もし、後者であれば、dRuby側でプロクシーに仕掛けをして
> dRubyオブジェクトのinspectはネットワークを越えないようにする
> 手もありますよね。
> 


とても長いっぷりは、RWikiのプロセスが1Gを超えるんですが
その根になるオブジェクトへのNoMethodErrorのときなどに
とても待たされます、って感じです。


自信の無さには自信があるので、最初にdRubyを疑いましたが、
リモートでなくても遅いようです。

nme.rb
--
a = Array.new(ARGV.shift.to_i)

begin
  a.foo
rescue
  Marshal.dump($!)
end
--

こんなのを書いて、profileとるとinspectが呼ばれているのがわかります。

% ruby -r profile nme.rb 10000
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 59.26     0.16      0.16        1   160.00   260.00  Array#inspect
 37.04     0.26      0.10    10000     0.01     0.01  NilClass#inspect
  3.70     0.27      0.01        1    10.00    10.00  Symbol#to_s
  0.00     0.27      0.00        1     0.00     0.00  Class#new
  0.00     0.27      0.00        1     0.00     0.00  NoMethodError#initialize
  0.00     0.27      0.00        1     0.00     0.00  Exception#exception
  0.00     0.27      0.00        1     0.00     0.00  NameError::message#!
  0.00     0.27      0.00        1     0.00     0.00  Exception#backtrace
  0.00     0.27      0.00        1     0.00     0.00  String#to_i
  0.00     0.27      0.00        1     0.00     0.00  NameError#initialize
  0.00     0.27      0.00        1     0.00   270.00  Marshal.dump
  0.00     0.27      0.00        1     0.00     0.00  Kernel.method_missing
  0.00     0.27      0.00        1     0.00     0.00  Exception#set_backtrace
  0.00     0.27      0.00        1     0.00     0.00  Exception#initialize
  0.00     0.27      0.00        1     0.00   270.00  NameError::message#_dump
  0.00     0.27      0.00        1     0.00     0.00  Array#initialize
  0.00     0.27      0.00        1     0.00     0.00  Array#shift
  0.00     0.27      0.00        1     0.00   270.00  #toplevel

% ruby -r profile nme.rb 1
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.00      0.00        1     0.00     0.00  Array#inspect
  0.00     0.00      0.00        1     0.00     0.00  Kernel.method_missing
  0.00     0.00      0.00        1     0.00     0.00  Marshal.dump
  0.00     0.00      0.00        1     0.00     0.00  String#to_i
  0.00     0.00      0.00        1     0.00     0.00  NoMethodError#initialize
  0.00     0.00      0.00        1     0.00     0.00  Exception#exception
  0.00     0.00      0.00        1     0.00     0.00  NameError::message#!
  0.00     0.00      0.00        1     0.00     0.00  Exception#backtrace
  0.00     0.00      0.00        1     0.00     0.00  Class#new
  0.00     0.00      0.00        1     0.00     0.00  NameError#initialize
  0.00     0.00      0.00        1     0.00     0.00  Symbol#to_s
  0.00     0.00      0.00        1     0.00     0.00  NilClass#inspect
  0.00     0.00      0.00        1     0.00     0.00  Exception#set_backtrace
  0.00     0.00      0.00        1     0.00     0.00  Exception#initialize
  0.00     0.00      0.00        1     0.00     0.00  NameError::message#_dump
  0.00     0.00      0.00        1     0.00     0.00  Array#initialize
  0.00     0.00      0.00        1     0.00     0.00  Array#shift
  0.00     0.01      0.00        1     0.00    10.00  #toplevel

で、Marshal.dumpをコメントアウトすると次のようにinspectは呼ばれません。

nme2.rb
--
a = Array.new(ARGV.shift.to_i)

begin
  a.foo
rescue
  # Marshal.dump($!)
end
--

% ruby -r profile nme2.rb 10000
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
  0.00     0.00      0.00        1     0.00     0.00  Kernel.method_missing
  0.00     0.00      0.00        1     0.00     0.00  String#to_i
  0.00     0.00      0.00        1     0.00     0.00  NoMethodError#initialize
  0.00     0.00      0.00        1     0.00     0.00  Exception#exception
  0.00     0.00      0.00        1     0.00     0.00  NameError::message#!
  0.00     0.00      0.00        1     0.00     0.00  Exception#backtrace
  0.00     0.00      0.00        1     0.00     0.00  Class#new
  0.00     0.00      0.00        1     0.00     0.00  NameError#initialize
  0.00     0.00      0.00        1     0.00     0.00  Exception#set_backtrace
  0.00     0.00      0.00        1     0.00     0.00  Exception#initialize
  0.00     0.00      0.00        1     0.00     0.00  Array#initialize
  0.00     0.00      0.00        1     0.00     0.00  Array#shift
  0.00     0.01      0.00        1     0.00    10.00  #toplevel



> |それで提案です。
> |
> |inspectは呼ばずに、いつもrb_any_to_s()、あるいは
> |
> |#<クラス名:オブジェクトid> 
> |
> |の形式(なんていうの?)をメッセージに入れるのはどうで
> |しょうか？
> 
> それだとnilやfalse、Fixnumのようなものまで
> 
> #<クラス名:オブジェクトid> 
> 
> になっちゃいますからねえ。




それで、error.cのname_err_mesg_to_str()を読みました。

1.8系はこんな感じです。1.9もほぼ同様です。

nil, true, falseはケアされてるみたい。

default:でinspectをした後に長さを数え、
それが長いときにrb_any_to_s()してるところが
あります。

	    d = rb_protect(rb_inspect, obj, 0);
	    if (NIL_P(d) || RSTRING(d)->len > 65) {
		d = rb_any_to_s(obj);
	    }

これを
	    d = rb_any_to_s(obj);

としていただけませんか、という提案です。

Marshal.dumpのほうは、

    rb_define_method(rb_cNameErrorMesg, "_dump", name_err_mesg_to_str, 1);

が関係あるのかなあと想像してます。


/* :nodoc: */
static VALUE
name_err_mesg_to_str(obj)
    VALUE obj;
{
    VALUE *ptr, mesg;
    Data_Get_Struct(obj, VALUE, ptr);

    mesg = ptr[0];
    if (NIL_P(mesg)) return Qnil;
    else {
	const char *desc = 0;
	VALUE d = 0, args[3];

	obj = ptr[1];
	switch (TYPE(obj)) {
	  case T_NIL:
	    desc = "nil";
	    break;
	  case T_TRUE:
	    desc = "true";
	    break;
	  case T_FALSE:
	    desc = "false";
	    break;
	  default:
	    d = rb_protect(rb_inspect, obj, 0);
	    if (NIL_P(d) || RSTRING(d)->len > 65) {
		d = rb_any_to_s(obj);
	    }
	    desc = RSTRING(d)->ptr;
	    break;
	}
	if (desc && desc[0] != '#') {
	    d = rb_str_new2(desc);
	    rb_str_cat2(d, ":");
	    rb_str_cat2(d, rb_obj_classname(obj));
	}
	args[0] = mesg;
	args[1] = ptr[2];
	args[2] = d;
	mesg = rb_f_sprintf(3, args);
    }
    if (OBJ_TAINTED(obj)) OBJ_TAINT(mesg);
    return mesg;
}