Performance Monitoring/profiling
At a higher level you can call:
[code]ruby script/performance/benchmarker ‘User.encrypted_password(“secret”, “salt”)’[/code]
Which returns a high level execution plan.
[code] user system total real
#1 0.000000 0.000000 0.000000 ( 0.000028)[/code]
If there’s a problem here you can then review the details using the profiler:
[code]ruby script/performance/profiler ‘User.encrypted_password(“secret”, “salt”)’[/code]
this translates to “Call the object.method using script/performance/profiler” . The above call spits out:
[code]Loading Rails…
Using the standard Ruby profiler.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
60.00 0.06 0.06 2 30.00 30.00 Hash#each
20.00 0.08 0.02 31 0.65 0.97 Array#each
10.00 0.09 0.01 7 1.43 1.43 Symbol#to_proc
10.00 0.10 0.01 4 2.50 2.50 Array#select
0.00 0.10 0.00 4 0.00 0.00 Array#<<
0.00 0.10 0.00 3 0.00 0.00 ActiveRecord::Validations::ClassMethods.write_inheritable_set
0.00 0.10 0.00 1 0.00 0.00 Dependencies.mechanism
0.00 0.10 0.00 1 0.00 0.00 Array#compact
0.00 0.10 0.00 1 0.00 0.00 Digest::Instance.digest
0.00 0.10 0.00 1 0.00 0.00 Kernel.require
0.00 0.10 0.00 15 0.00 2.00 Array#collect
0.00 0.10 0.00 1 0.00 0.00 Inflector.underscore
0.00 0.10 0.00 9 0.00 0.00 Object#method_added
0.00 0.10 0.00 10 0.00 0.00 String#==
0.00 0.10 0.00 14 0.00 0.00 Kernel.hash
0.00 0.10 0.00 8 0.00 7.50 Enumerable.inject
0.00 0.10 0.00 5 0.00 0.00 Kernel.equal?
0.00 0.10 0.00 11 0.00 0.00 Class#inheritable_attributes
0.00 0.10 0.00 2 0.00 0.00 Array#pop
0.00 0.10 0.00 5 0.00 2.00 Dependencies.log_call
0.00 0.10 0.00 1 0.00 100.00 Dependencies.load_file
0.00 0.10 0.00 17 0.00 0.00 Hash#[]=
0.00 0.10 0.00 8 0.00 0.00 Object#initialize
0.00 0.10 0.00 2 0.00 0.00 Array#delete_if
0.00 0.10 0.00 2 0.00 0.00 Kernel.inspect
0.00 0.10 0.00 1 0.00 0.00 Dependencies.search_for_file
0.00 0.10 0.00 5 0.00 0.00 Symbol#===
0.00 0.10 0.00 5 0.00 0.00 String#inspect
0.00 0.10 0.00 20 0.00 0.00 Module#constants
0.00 0.10 0.00 1 0.00 20.00 Object#require
0.00 0.10 0.00 1 0.00 0.00 Observable.notify_observers
0.00 0.10 0.00 3 0.00 0.00 String#blank?
0.00 0.10 0.00 1 0.00 0.00 Kernel.==
0.00 0.10 0.00 1 0.00 0.00 Digest::Class#hexdigest
0.00 0.10 0.00 3 0.00 0.00 Kernel.send
0.00 0.10 0.00 4 0.00 0.00 String#+
0.00 0.10 0.00 2 0.00 30.00 ActiveSupport::CoreExtensions::Hash::Keys.symbolize_keys
0.00 0.10 0.00 4 0.00 7.50 Module#local_constants
0.00 0.10 0.00 1 0.00 0.00 Dependencies.qualified_name_for
0.00 0.10 0.00 5 0.00 0.00 String#to_s
0.00 0.10 0.00 1 0.00 0.00 Dependencies.load_once_paths
0.00 0.10 0.00 4 0.00 0.00 ActiveSupport::CoreExtensions::String::Inflections.constantize
0.00 0.10 0.00 1 0.00 0.00 Kernel.gem_original_require
0.00 0.10 0.00 14 0.00 0.00 Kernel.is_a?
0.00 0.10 0.00 1 0.00 0.00 Digest::Class#digest
0.00 0.10 0.00 1 0.00 100.00 Dependencies.load_missing_constant
0.00 0.10 0.00 2 0.00 0.00 Kernel.singleton_method_added
0.00 0.10 0.00 1 0.00 10.00 ActiveRecord::Validations::ClassMethods.validates_uniqueness_of
0.00 0.10 0.00 30 0.00 0.00 Module#==
0.00 0.10 0.00 1 0.00 0.00 Class#new
0.00 0.10 0.00 14 0.00 0.00 File#expand_path
0.00 0.10 0.00 4 0.00 0.00 Module#ancestors
0.00 0.10 0.00 1 0.00 0.00 ActiveSupport::CoreExtensions::String::Inflections.underscore
0.00 0.10 0.00 2 0.00 0.00 Hash#include?
0.00 0.10 0.00 1 0.00 0.00 User#encrypted_password
0.00 0.10 0.00 1 0.00 0.00 Enumerable.any?
0.00 0.10 0.00 3 0.00 0.00 Dependencies.loaded
0.00 0.10 0.00 1 0.00 0.00 String#tr
0.00 0.10 0.00 3 0.00 0.00 Kernel.block_given?
0.00 0.10 0.00 1 0.00 0.00 ActiveRecord::Validations::ClassMethods.validates_presence_of
0.00 0.10 0.00 2 0.00 0.00 String#size
0.00 0.10 0.00 2 0.00 0.00 Hash#default
0.00 0.10 0.00 1 0.00 0.00 NilClass#nil?
0.00 0.10 0.00 10 0.00 0.00 Fixnum#==
0.00 0.10 0.00 6 0.00 0.00 String#split
0.00 0.10 0.00 1 0.00 0.00 Dependencies.load?
0.00 0.10 0.00 1 0.00 50.00 ActiveRecord::Validations::ClassMethods.validates_confirmation_of
0.00 0.10 0.00 2 0.00 0.00 Array#-
0.00 0.10 0.00 9 0.00 0.00 Module#blank_slate_method_added
0.00 0.10 0.00 2 0.00 30.00 ActiveRecord::Validations::ClassMethods.validates_each
0.00 0.10 0.00 1 0.00 0.00 Module#private
0.00 0.10 0.00 849 0.00 0.00 Hash#key?
0.00 0.10 0.00 2 0.00 0.00 Kernel.respond_to?
0.00 0.10 0.00 2 0.00 0.00 Module#attr_accessor
0.00 0.10 0.00 12 0.00 0.00 Array#shift
0.00 0.10 0.00 1 0.00 100.00 Dependencies.require_or_load
0.00 0.10 0.00 9 0.00 0.00 Dependencies.log_activity
0.00 0.10 0.00 5 0.00 0.00 Array#last
0.00 0.10 0.00 4 0.00 0.00 Inflector.constantize
0.00 0.10 0.00 1 0.00 0.00 Array#uniq
0.00 0.10 0.00 18 0.00 0.00 Kernel.object_id
0.00 0.10 0.00 3 0.00 0.00 Class#read_inheritable_attribute
0.00 0.10 0.00 2 0.00 0.00 Symbol#inspect
0.00 0.10 0.00 1 0.00 100.00 Module#const_missing
0.00 0.10 0.00 1 0.00 0.00 ActiveRecord::Base#inherited
0.00 0.10 0.00 3 0.00 0.00 Array#|
0.00 0.10 0.00 11 0.00 0.00 Regexp#escape
0.00 0.10 0.00 1 0.00 0.00 Dependencies.load_once_path?
0.00 0.10 0.00 5 0.00 0.00 Kernel.caller
0.00 0.10 0.00 3 0.00 0.00 Module#===
0.00 0.10 0.00 8 0.00 0.00 Module#const_defined?
0.00 0.10 0.00 4 0.00 0.00 File#file?
0.00 0.10 0.00 1 0.00 0.00 String#downcase
0.00 0.10 0.00 11 0.00 0.00 Array#first
0.00 0.10 0.00 1 0.00 0.00 Dependencies.warnings_on_first_load
0.00 0.10 0.00 1 0.00 0.00 Digest::Base#update
0.00 0.10 0.00 2 0.00 0.00 Digest::Base#reset
0.00 0.10 0.00 2 0.00 0.00 Class#inherited
0.00 0.10 0.00 2 0.00 0.00 Set#include?
0.00 0.10 0.00 2 0.00 60.00 Dependencies.new_constants_in
0.00 0.10 0.00 2 0.00 0.00 Dependencies.load_paths
0.00 0.10 0.00 12 0.00 0.00 Kernel.__send__
0.00 0.10 0.00 1 0.00 0.00 Fixnum#-@
0.00 0.10 0.00 1 0.00 0.00 ActiveSupport::CoreExtensions::String::StartsEndsWith.ends_with?
0.00 0.10 0.00 4 0.00 0.00 Module#module_eval
0.00 0.10 0.00 15 0.00 0.00 Hash#[]
0.00 0.10 0.00 6 0.00 0.00 Dependencies.qualified_const_defined?
0.00 0.10 0.00 6 0.00 0.00 Module#name
0.00 0.10 0.00 1 0.00 0.00 NilClass#inspect
0.00 0.10 0.00 1 0.00 0.00 Dependencies.loadable_constants_for_path
0.00 0.10 0.00 1 0.00 0.00 NameError#initialize
0.00 0.10 0.00 2 0.00 0.00 String#length
0.00 0.10 0.00 2 0.00 0.00 Module#to_s
0.00 0.10 0.00 1 0.00 0.00 Digest::Base#finish
0.00 0.10 0.00 4 0.00 0.00 Symbol#to_sym
0.00 0.10 0.00 5 0.00 0.00 Array#flatten
0.00 0.10 0.00 7 0.00 0.00 Proc#new
0.00 0.10 0.00 6 0.00 0.00 Array#concat
0.00 0.10 0.00 2 0.00 0.00 ActiveSupport::CoreExtensions::String::Inflections.camelize
0.00 0.10 0.00 1 0.00 0.00 Array#map
0.00 0.10 0.00 3 0.00 0.00 ActiveRecord::Validations::ClassMethods.validate
0.00 0.10 0.00 1 0.00 0.00 Exception#initialize
0.00 0.10 0.00 3 0.00 0.00 Class#write_inheritable_attribute
0.00 0.10 0.00 1 0.00 0.00 Array#inspect
0.00 0.10 0.00 3 0.00 0.00 ActiveRecord::Errors#default_error_messages
0.00 0.10 0.00 2 0.00 0.00 Dependencies.autoloaded_constants
0.00 0.10 0.00 1 0.00 80.00 Kernel.load_without_new_constant_marking
0.00 0.10 0.00 4 0.00 0.00 File#join
0.00 0.10 0.00 3 0.00 0.00 Symbol#to_s
0.00 0.10 0.00 1 0.00 0.00 Dependencies.history
0.00 0.10 0.00 13 0.00 0.00 String#empty?
0.00 0.10 0.00 2 0.00 0.00 Set#<<
0.00 0.10 0.00 7 0.00 0.00 String#gsub
0.00 0.10 0.00 1 0.00 100.00 Object#profile_me
0.00 0.10 0.00 1 0.00 100.00 Class#const_missing
0.00 0.10 0.00 1 0.00 0.00 Array#uniq!
0.00 0.10 0.00 3 0.00 0.00 String#strip
0.00 0.10 0.00 6 0.00 0.00 Dependencies.constant_watch_stack
0.00 0.10 0.00 3 0.00 0.00 Array#empty?
0.00 0.10 0.00 1 0.00 0.00 Observable.changed
0.00 0.10 0.00 2 0.00 0.00 Kernel.instance_variable_set
0.00 0.10 0.00 2 0.00 0.00 Inflector.camelize
0.00 0.10 0.00 7 0.00 0.00 Array#include?
0.00 0.10 0.00 3 0.00 0.00 ActiveRecord::Validations::ClassMethods.validation_method
0.00 0.10 0.00 9 0.00 0.00 Dependencies.log
0.00 0.10 0.00 1 0.00 0.00 Dependencies.to_constant_name
0.00 0.10 0.00 3 0.00 0.00 String#upcase
0.00 0.10 0.00 1 0.00 0.00 ActiveRecord::Observing::ClassMethods.inherited
0.00 0.10 0.00 8 0.00 0.00 Array#*
0.00 0.10 0.00 7 0.00 0.00 String#[]
0.00 0.10 0.00 17 0.00 0.00 Module#const_get
0.00 0.10 0.00 1 0.00 100.00 #toplevel[/code]
A detailed break down of the object.method call - great for tracing problems down.
All of this ties in nicely with the ability to run performance based unit tests.