From: Ryan Davis <ryand@...>
Date: 2004-03-15T14:44:24+09:00
Subject: Pathological slowdown in 1.8

Hi all,

I have some software that brings out a pathological condition that 
makes the code much slower in ruby 1.8 than it runs in 1.6. I've 
measured as much as 5000% slower with the test code. I believe the 
slowdown comes from extra calls to inspect during an exception for a 
missing method. The situation gets exponentially slower if the receiver 
is a  massively cyclic object graph that has not overridden #inspect.

I've patched eval.c to print out the reciever's class and method in 
rb_call0 to determine what is being called so much and got the 
following:

<594> make ruby18 && 2>&1 ./ruby18 slow.rb 500 | occur | head -5
make: `ruby18' is up to date.
2251504: call0: Fixnum#==
  501000: call0: Kernel#inspect
    1500: call0: Exception#backtrace
    1009: call0: Class#(null)
     505: call0: Class#new

With my patch applied I get (without -d):

  1009: call0: Class#(null)
  1005: call0: Class#new
   501: call0: Top#map
   500: call0: Kernel#method_missing
   500: call0: Map#add

and with -d it looks pretty much the same as without the patch.

Below is the minimally reproducible test code and an unsatisfactory 
(read: HORRID) patch that does make the behavior go away only if you 
aren't running with -d (which seems like the correct course of 
action--we ARE causing an error, and you'd want to know more w/ -d). 
PLEASE PLEASE PLEASE school me on what the correct patch should be. I 
was torn between rb_eval and name_err_mesg_to_str (which I couldn't 
prove was the actual culprit).

#!/usr/bin/ruby -w

$iterations  = (ARGV[0] || 1_000).to_i

puts "iter=#{$iterations}"

class Map
   attr_reader :members
   def initialize
     @members = []
   end

   def add(thing)
     @members << thing
   end
end

class Top
   attr_reader :map
   def initialize
     @map = Map.new
   end
end

class Page
   def initialize(t)
     @top = t
     @top.map.add(self)
   end

   def do_bad_things
     begin
       # huh... eval doesn't seem to matter.
       # I thought for some reason that it did.
       # eval "notAMethod"
       self.notAMethod
     rescue NameError
       99
     end
   end
end

top = Top.new

$iterations.times do |i|
   Page.new(top)
end

top.map.members.each do |page|
   page.do_bad_things
end

========

Index: eval.c
===================================================================
RCS file: /src/ruby/eval.c,v
retrieving revision 1.616.2.15
diff -d -u -r1.616.2.15 eval.c
--- eval.c	10 Mar 2004 08:20:58 -0000	1.616.2.15
+++ eval.c	14 Mar 2004 06:00:25 -0000
@@ -5323,9 +5323,17 @@
  	if (exc == rb_eNoMethodError) {
  	    args[n++] = rb_ary_new4(argc-1, argv+1);
  	}
-	exc = rb_class_new_instance(n, args, exc);
+	if (ruby_debug == Qtrue) {
+	  exc = rb_class_new_instance(n, args, exc);
+	}
  	ruby_frame = ruby_frame->prev; /* pop frame for "method_missing" */
-	rb_exc_raise(exc);
+
+	if (ruby_debug == Qtrue) {
+	  rb_exc_raise(exc);
+	} else {
+	  rb_raise(rb_eNameError, format, rb_id2name(id),
+		   "something bad", ":", rb_class2name(CLASS_OF(obj)));
+	}
      }

      return Qnil;		/* not reached */

BTW, besides that beautiful book you guys showed at the last rubyconf, 
is there a internals/debugging guide somewhere that we might be able to 
get translated into English? I've been tempted to try to get a fund 
going that will pay for translations of the japanese doco and books. 
This would be near the top of my list.