 |
Forums |
Admin Discussion Forums: help Start New Thread
By: Charlie Savage
 RE: Why am I seeing percentages > 100% [ reply ]
2008-11-03 07:38
|
Hi Rick,
Can you retest this with ruby-prof 0.7.0 (out this week) and see if it still happens?
As for sorting children, I don't think they are actually sorted at all right now.
Happy to take a patch. I'd say add a <=> method to call_info (see same code in method_info) and the then update the printers. Note that its standard to sort from lowest to highest in Ruby. That means the printers and tests have code like this:
methods.sort.reverse
To go from highest to lowest.
Thanks - Charlie
|
By: Rick DeNatale
Why am I seeing percentages > 100% [ reply ]
2008-09-23 22:26
|
I'm trying to tune the performance of the startup for a large rails app.
I wrote this script file script/profile_startup
#!/usr/bin/env ruby
require File.dirname(__FILE__) + '/../config/boot'
ENV['RAILS_ENV'] = case ARGV.first
when "p": "production"
when "d": "development"
when "t": "test"
else
ARGV.first || ENV['RAILS_ENV'] || 'development'
end
require 'ruby-prof'
output_path = File.join(RAILS_ROOT, 'doc', "profile")
puts "profiling to #{output_path}"
puts "Loading #{ENV['RAILS_ENV']} environment"
result = RubyProf.profile do
require File.dirname(__FILE__) + '/../config/environment'
end
printer = RubyProf::GraphPrinter.new(result)
File.open(output_path + "_graph.txt", "w") do | file |
printer.print(file, :min_percent => 0)
end
When I run this, the beginning of the output looks like this:
Thread ID: 214780
Total Time: 0.01
%total %self total self wait child calls Name
--------------------------------------------------------------------------------
0.00% 0.00% 0.00 0.00 0.00 0.00 0 Kernel#gem_original_require
0.00 0.00 0.00 0.00 1/1 <Class::NearTime::Configuration>#load
27.23 0.00 0.00 27.23 1/1 <Class::Rails::Initializer>#run
0.00 0.00 0.00 0.00 1/7969 Kernel#==
0.01 0.00 0.00 0.01 1/228 Object#require
0.00 0.00 0.00 0.00 1/20944 <Class::File>#join
0.01 0.00 0.00 0.01 1/33 Kernel#gem
0.00 0.00 0.00 0.00 1/51 <Object::Object>#[]
0.00 0.00 0.00 0.00 1/139 <Class::File>#dirname
0.68 0.00 0.00 0.68 3/222 Kernel#require-1
0.00 0.00 0.00 0.00 1/5311 Module#method_added
0.00 0.00 0.00 0.00 1/29342 Kernel#respond_to?
0.00 0.00 0.00 0.00 1/9282 <Class::Object>#allocate
0.00 0.00 0.00 0.00 1/10784 Class#new
--------------------------------------------------------------------------------
0.05% 0.00% 0.00 0.00 0.00 0.00 0 Global#[No method]
0.00 0.00 0.00 0.00 1/838 String#+
0.00 0.00 0.00 0.00 1/139 <Class::File>#dirname
--------------------------------------------------------------------------------
0.00% 0.00% 0.00 0.00 0.00 0.00 0 Kernel#require
--------------------------------------------------------------------------------
27.23 0.00 0.00 27.23 1/1 Kernel#gem_original_require
272288.76% 1.24% 27.23 0.00 0.00 27.23 1 <Class::Rails::Initializer>#run
0.00 0.00 0.00 0.00 1/5333 <Class::Dir>#[]
0.00 0.00 0.00 0.00 1/3 Array#reject
0.00 0.00 0.00 0.00 1/12808 Kernel#block_given?
27.23 0.00 0.00 27.22 1/6 Kernel#send
0.00 0.00 0.00 0.00 1/20944 <Class::File>#join
0.00 0.00 0.00 0.00 5/12 Rails::OrderedOptions#method_missing
0.00 0.00 0.00 0.00 2/1864 Array#+
0.00 0.00 0.00 0.00 2/2523 Array#map
0.00 0.00 0.00 0.00 1/8 <Class::Dir>#entries
0.00 0.00 0.00 0.00 1/10784 Class#new
0.00 0.00 0.00 0.00 1/2 Rails::Configuration#plugins=
0.00 0.00 0.00 0.00 1/8374 Array#select
--------------------------------------------------------------------------------
...
So the first question is why 272288.76% ?
The total thread time of 0.01 is suspicious.
Second, is there any reason why the children method invocations shouldn't be sorted by decreasing time in order to make it easier to see which children are taking up the most time?
I was thinking of doing a patch to sort the children by the max of their self and child times.
Does this make sense or am I missing something?
|
|
|
