Skip to content

Instantly share code, notes, and snippets.

@agrimm

agrimm/commands_run.txt

Last active January 3, 2016 12:39
Show Gist options
  • Save agrimm/8464764 to your computer and use it in GitHub Desktop.
Save agrimm/8464764 to your computer and use it in GitHub Desktop.
Download ZIP
Replication of bug in ruby-prof where time taken by a particular child is underestimated
Raw
commands_run.txt
bundle exec ruby-prof --printer=graph --file=graph_slow_search.txt slow_search.rb
ruby --version
ruby 2.2.0dev (2014-01-10 trunk 44549) [x86_64-linux]
########
$ rbenv shell 2.2.0-dev
$ RUBY_PROF_TRACE=/tmp/ruby-prof-trace.txt bundle exec ruby-prof --printer=graph --file=not_used.txt slow_search.rb
$ cd ../sandbox/ruby-prof/
$ ruby bin/ruby-prof-check-trace /tmp/ruby-prof-trace.txt
LINE 2: return event without call: RubyProf::Profile#start
STACK: []
fixing stack
LINE 3: return event without call: Module#start
STACK: []
fixing stack
LINE 600057: return event without call: Module#start_script
STACK: []
fixing stack
LINE 600058: return event without call: RubyProf::Cmd#run
STACK: []
fixing stack
LINE 600059: return event without call: Kernel#load
STACK: []
fixing stack
{140730833233521=>{140730847870881=>["Module#stop", "RubyProf::Profile#stop"]}}
Raw
graph_slow_search.txt
Thread ID: 69827543364400
Fiber ID: 69827550682020
Total Time: 3.4181087569999997
Sort by: total_time
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
100.00% 0.00% 3.418 0.000 0.000 3.418 2 Global#[No method]
3.418 0.000 0.000 3.418 1/2 Array#each
0.000 0.000 0.000 0.000 3/3 Class#inherited
0.000 0.000 0.000 0.000 2/2 Module#method_added
0.000 0.000 0.000 0.000 1/1 BasicObject#singleton_method_added
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/2 Enumerable#find
3.418 0.000 0.000 3.418 1/2 Global#[No method]
100.00% 0.00% 3.418 0.000 0.000 3.418 2 *Array#each
3.418 0.000 0.000 3.418 1/1 <Class::MainClass>#main_method
3.361 0.129 0.000 3.232 100000/100000 SlowClass#time_sink
--------------------------------------------------------------------------------
3.418 0.000 0.000 3.418 1/1 Array#each
100.00% 0.00% 3.418 0.000 0.000 3.418 1 <Class::MainClass>#main_method
3.418 0.000 0.000 3.418 1/1 SlowSearcher#do_find
0.000 0.000 0.000 0.000 1/1 Array#*
0.000 0.000 0.000 0.000 2/2 Class#new
--------------------------------------------------------------------------------
3.418 0.000 0.000 3.418 1/1 <Class::MainClass>#main_method
99.99% 0.00% 3.418 0.000 0.000 3.418 1 SlowSearcher#do_find
3.418 0.000 0.000 3.418 1/1 Enumerable#find
0.000 0.000 0.000 0.000 1/1 Symbol#to_proc
--------------------------------------------------------------------------------
3.418 0.000 0.000 3.418 1/1 SlowSearcher#do_find
99.99% 0.00% 3.418 0.000 0.000 3.418 1 Enumerable#find
0.000 0.000 0.000 0.000 1/2 Array#each
--------------------------------------------------------------------------------
3.361 0.129 0.000 3.232 100000/100000 Array#each
98.33% 3.78% 3.361 0.129 0.000 3.232 100000 SlowClass#time_sink
3.232 3.232 0.000 0.000 100000/100000 Fixnum#**
--------------------------------------------------------------------------------
3.232 3.232 0.000 0.000 100000/100000 SlowClass#time_sink
94.55% 94.55% 3.232 3.232 0.000 0.000 100000 Fixnum#**
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 <Class::MainClass>#main_method
0.01% 0.01% 0.000 0.000 0.000 0.000 1 Array#*
--------------------------------------------------------------------------------
0.00% 0.00% 0.000 0.000 0.000 0.000 2 IO#set_encoding
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 <Class::MainClass>#main_method
0.00% 0.00% 0.000 0.000 0.000 0.000 2 Class#new
0.000 0.000 0.000 0.000 2/2 BasicObject#initialize
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 3/3 Global#[No method]
0.00% 0.00% 0.000 0.000 0.000 0.000 3 Class#inherited
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 SlowSearcher#do_find
0.00% 0.00% 0.000 0.000 0.000 0.000 1 Symbol#to_proc
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 Global#[No method]
0.00% 0.00% 0.000 0.000 0.000 0.000 2 Module#method_added
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 2/2 Class#new
0.00% 0.00% 0.000 0.000 0.000 0.000 2 BasicObject#initialize
--------------------------------------------------------------------------------
0.000 0.000 0.000 0.000 1/1 Global#[No method]
0.00% 0.00% 0.000 0.000 0.000 0.000 1 BasicObject#singleton_method_added
* indicates recursively called methods
Raw
slow_search.rb
class SlowClass
def time_sink
1234567890 ** 300
false
end
end
class SlowSearcher
def do_find(slow_objects)
slow_objects.find(&:time_sink)
end
end
class MainClass
def self.main_method
slow_objects = [SlowClass.new] * 100_000
slow_searcher = SlowSearcher.new
slow_searcher.do_find(slow_objects)
end
end
[1].each do
MainClass.main_method
end
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment