From: Mauricio Fernandez Date: 2006-06-22T17:23:17+09:00 Subject: Re: ruby-prof-0.4.0 --FCuugMFkClbJLl1L Content-Type: text/plain; charset=iso-8859-1 Content-Disposition: inline Content-Transfer-Encoding: 8bit On Thu, Jun 22, 2006 at 04:19:58AM +0900, Charlie Savage wrote: > Shugo and I are happy to announce the release of ruby-prof 0.4.0, which > is chock full of new features: > > * Addition of call graph profiles similar to GProf > > * Improved speed - overhead is now as low as 15% for some code, although > you should generally expect around 50% I tried to profile rcov (while running its own unit tests), and ran into this: $ ruby-prof -p graph_html -c cpu -f prof.html bin/rcov -- -I lib:ext/rcovrt/ -T --no-html test/test_* Loaded suite /home/batsman/usr/bin/ruby-prof Started ......................................... Finished in 3.660745 seconds. 41 tests, 438 assertions, 0 failures, 0 errors +----------------------------------------------------+-------+-------+--------+ | File | Lines | LOC | COV | +----------------------------------------------------+-------+-------+--------+ |lib/rcov.rb | 934 | 558 | 88.0% | +----------------------------------------------------+-------+-------+--------+ |Total | 934 | 558 | 88.0% | +----------------------------------------------------+-------+-------+--------+ 88.0% 1 file(s) 934 Lines 558 LOC /home/batsman/usr/lib/ruby/gems/1.8/gems/ruby-prof-0.4.0/bin/ruby-prof:128:in `stop': The name has already been assigned to another method. This is a bug - please report it. (RuntimeError) from /home/batsman/usr/lib/ruby/gems/1.8/gems/ruby-prof-0.4.0/bin/ruby-prof:128 I applied this to see what was going on: --- ruby_prof.c.orig 2006-06-22 09:40:32.000000000 +0200 +++ ruby_prof.c.mod 2006-06-22 09:42:07.000000000 +0200 @@ -880,7 +880,7 @@ /* Definitely should never happen! */ rb_raise(rb_eRuntimeError, "The name %s has already been assigned to another method. This is a bug - please report it.", - name); + StringValuePtr(name)); } rb_hash_aset(hash, name, prof_method_new(method)); ... and found what is causing the problem. rcov's tests do something like: batsman@tux-chan:~/mess/current$ cat ruby-prof-bomb.rb str = %{module Foo; class Bar; def foo; end end end} eval str Foo::Bar.new.foo Object.class_eval{ remove_const :Foo } eval str Foo::Bar.new.foo batsman@tux-chan:~/mess/current$ ruby-prof -p graph ruby-prof-bomb.rb /home/batsman/usr/lib/ruby/gems/1.8/gems/ruby-prof-0.4.0/bin/ruby-prof:128:in `stop': The name Foo::Bar#foo has already been assigned to another method. This is a bug - please report it. (RuntimeError) from /home/batsman/usr/lib/ruby/gems/1.8/gems/ruby-prof-0.4.0/bin/ruby-prof:128 from /home/batsman/usr/bin/ruby-prof:18 I really wanted to get a call graph, so I applied the following na�ve patch: --- ruby_prof.c.orig 2006-06-22 09:40:32.000000000 +0200 +++ ruby_prof.c 2006-06-22 09:42:53.000000000 +0200 @@ -875,12 +875,9 @@ overwrite the reference to the other prof_method. That will mean that Ruby will garbage collect it wreaking all sorts of havoc! Trust me - this one took a long time to track down. */ - if (existing_value != Qnil) - { - /* Definitely should never happen! */ - rb_raise(rb_eRuntimeError, - "The name %s has already been assigned to another method. This is a bug - please report it.", - name); + while(existing_value != Qnil) { + rb_str_cat(name, "'", 1); + existing_value = rb_hash_aref(hash, name); } rb_hash_aset(hash, name, prof_method_new(method)); ruby_prof seems to work now, and there are two separate entries in the call graph for Foo::Bar#foo (see the attached ruby-prof-out-ok.txt). I think keeping them that way, as opposed to consolidating them, makes sense, since they could have been entirely different methods. Before I forget, a minor nitpick }:) Could you release a tarball through Rubyforge, in addition to the RubyGems packages? Some systems like FreeBSD's ports are happier when there's an online accessible tarball. Other repackagers will appreciate too. -- Mauricio Fernandez - http://eigenclass.org - singular Ruby --FCuugMFkClbJLl1L Content-Type: text/plain; charset=us-ascii Content-Disposition: attachment; filename="ruby-prof-out-ok.txt" $ cat ruby-prof-bomb2.rb str = %{module Foo; class Bar; def foo; end end end} eval str Foo::Bar.new.foo Object.class_eval{ remove_const :Foo } eval str Foo::Bar.new.foo Foo::Bar.new.foo $ ruby-prof -p graph ruby-prof-bomb2.rb Thread ID: -605342748 %total %self total self children calls Name -------------------------------------------------------------------------------- 0.00% 0.00% 0.00 0.00 0.00 1 #toplevel 0.00 0.00 0.00 1/1 Kernel#load -------------------------------------------------------------------------------- 0.00 0.00 0.00 2/2 Kernel#load 0.00% 0.00% 0.00 0.00 0.00 2 Foo::Bar#foo -------------------------------------------------------------------------------- 0.00 0.00 0.00 3/3 Class#new 0.00% 0.00% 0.00 0.00 0.00 3 Object#initialize -------------------------------------------------------------------------------- 0.00 0.00 0.00 1/1 Kernel#load 0.00% 0.00% 0.00 0.00 0.00 1 Module#class_eval 0.00 0.00 0.00 1/1 Module#remove_const -------------------------------------------------------------------------------- 0.00 0.00 0.00 2/2 Kernel#load 0.00% 0.00% 0.00 0.00 0.00 2 Kernel#eval 0.00 0.00 0.00 2/2 Module#method_added 0.00 0.00 0.00 2/2 Class#inherited -------------------------------------------------------------------------------- 0.00 0.00 0.00 1/1 Module#class_eval 0.00% 0.00% 0.00 0.00 0.00 1 Module#remove_const -------------------------------------------------------------------------------- 0.00 0.00 0.00 2/2 Kernel#eval 0.00% 0.00% 0.00 0.00 0.00 2 Class#inherited -------------------------------------------------------------------------------- 0.00 0.00 0.00 2/2 Kernel#eval 0.00% 0.00% 0.00 0.00 0.00 2 Module#method_added -------------------------------------------------------------------------------- 0.00 0.00 0.00 1/1 Kernel#load 0.00% 0.00% 0.00 0.00 0.00 1 Foo::Bar#foo -------------------------------------------------------------------------------- 0.00 0.00 0.00 1/1 #toplevel 0.00% 0.00% 0.00 0.00 0.00 1 Kernel#load 0.00 0.00 0.00 1/2 Foo::Bar#foo 0.00 0.00 0.00 2/2 Kernel#eval 0.00 0.00 0.00 1/1 Module#class_eval 0.00 0.00 0.00 3/3 Class#new -------------------------------------------------------------------------------- 0.00 0.00 0.00 3/3 Kernel#load 0.00% 0.00% 0.00 0.00 0.00 3 Class#new 0.00 0.00 0.00 3/3 #allocate 0.00 0.00 0.00 3/3 Object#initialize -------------------------------------------------------------------------------- 0.00 0.00 0.00 3/3 Class#new 0.00% 0.00% 0.00 0.00 0.00 3 #allocate --FCuugMFkClbJLl1L--