Greg's Blog

helping me remember what I figure out

Performance Monitoring/profiling

| Comments

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.