From f7866cdac12aecd332b71de4884664d54b0aef20 Mon Sep 17 00:00:00 2001 From: Jeremy Kemper Date: Sun, 15 Jun 2008 14:41:18 -0700 Subject: Extract Metric and Performer. Simplify and refactor. --- .../lib/active_support/testing/performance.rb | 350 +++++++++++++-------- 1 file changed, 212 insertions(+), 138 deletions(-) (limited to 'activesupport/lib') diff --git a/activesupport/lib/active_support/testing/performance.rb b/activesupport/lib/active_support/testing/performance.rb index 38722ecb8b..4440f10647 100644 --- a/activesupport/lib/active_support/testing/performance.rb +++ b/activesupport/lib/active_support/testing/performance.rb @@ -12,18 +12,22 @@ module ActiveSupport DEFAULTS = { :benchmark => benchmark, - :runs => benchmark ? 20 : 4, - :min_percent => 0.05, - :metrics => [:process_time, :memory, :allocations], + :runs => benchmark ? 10 : 1, + :min_percent => 0.02, + :metrics => [:process_time, :wall_time, :cpu_time, :memory, :objects], :formats => [:flat, :graph_html, :call_tree], - :output => 'tmp/performance' } + :output => 'tmp/performance' + } def self.included(base) - base.extend ClassMethods - base.class_inheritable_accessor :profile_options + base.class_inheritable_hash :profile_options base.profile_options = DEFAULTS.dup end + def full_test_name + "#{self.class.name}##{method_name}" + end + def run(result) return if method_name =~ /^default_test$/ @@ -31,153 +35,122 @@ module ActiveSupport @_result = result run_warmup - - self.class.measure_modes.each do |measure_mode| - data = run_profile(measure_mode) - self.class.report_profile_total(data, measure_mode) - self.class.record_results(full_test_name, data, measure_mode) - result.add_run + profile_options[:metrics].each do |metric_name| + if klass = Metrics[metric_name.to_sym] + run_profile(klass.new) + result.add_run + else + $stderr.puts "Skipping unknown metric #{metric_name.inspect}. Expected :process_time, :wall_time, :cpu_time, :memory, or :objects." + end end yield(self.class::FINISHED, name) end - protected - def full_test_name - "#{self.class.name}##{@method_name}" - end - - def run_test - run_callbacks :setup - setup - yield + def run_test(metric, mode) + run_callbacks :setup + setup + metric.send(mode) { __send__ @method_name } + rescue ::Test::Unit::AssertionFailedError => e + add_failure(e.message, e.backtrace) + rescue StandardError, ScriptError + add_error($!) + ensure + begin + teardown + run_callbacks :teardown, :enumerator => :reverse_each rescue ::Test::Unit::AssertionFailedError => e add_failure(e.message, e.backtrace) rescue StandardError, ScriptError add_error($!) - ensure - begin - teardown - run_callbacks :teardown, :enumerator => :reverse_each - rescue ::Test::Unit::AssertionFailedError => e - add_failure(e.message, e.backtrace) - rescue StandardError, ScriptError - add_error($!) - end end + end + protected def run_warmup - puts - print full_test_name - - run_test do - bench = Benchmark.realtime do - __send__(@method_name) - end - puts " (%.2fs warmup)" % bench - end + time = Metrics::Time.new + run_test(time, :benchmark) + puts "%s (%s warmup)" % [full_test_name, time.format(time.total)] end - def run_profile(measure_mode) - RubyProf.benchmarking = profile_options[:benchmark] - RubyProf.measure_mode = measure_mode + def run_profile(metric) + klass = profile_options[:benchmark] ? Benchmarker : Profiler + performer = klass.new(self, metric) - print ' ' - profile_options[:runs].times do |i| - run_test do - begin - GC.disable - RubyProf.resume { __send__(@method_name) } - print '.' - $stdout.flush - ensure - GC.enable - end - end - end - - RubyProf.stop - end - - module ClassMethods - def record_results(test_name, data, measure_mode) - if RubyProf.benchmarking? - record_benchmark(test_name, data, measure_mode) - else - record_profile(test_name, data, measure_mode) - end + performer.run + puts performer.report + performer.record end - def report_profile_total(data, measure_mode) - total_time = - if RubyProf.benchmarking? - data - else - data.threads.values.sum(0) do |method_infos| - method_infos.sort.last.total_time - end - end + class Performer + delegate :profile_options, :full_test_name, :to => :@harness - format = - case measure_mode - when RubyProf::PROCESS_TIME, RubyProf::WALL_TIME - "%.2f seconds" - when RubyProf::MEMORY - "%.2f bytes" - when RubyProf::ALLOCATIONS - "%d allocations" - else - "%.2f #{measure_mode}" - end + def initialize(harness, metric) + @harness, @metric = harness, metric + end - total = format % total_time - puts "\n #{ActiveSupport::Testing::Performance::Util.metric_name(measure_mode)}: #{total}\n" + def report + rate = @total / profile_options[:runs] + '%20s: %s/run' % [@metric.name, @metric.format(rate)] end + end - def measure_modes - ActiveSupport::Testing::Performance::Util.measure_modes(profile_options[:metrics]) + class Benchmarker < Performer + def run + profile_options[:runs].times { @harness.run_test(@metric, :benchmark) } + @total = @metric.total end - def printer_classes - ActiveSupport::Testing::Performance::Util.printer_classes(profile_options[:formats]) + def record + with_output_file do |file| + file.puts [full_test_name, @metric.name, + @metric.total, profile_options[:runs], + @metric.total / profile_options[:runs], + Time.now.utc.xmlschema, + Rails::VERSION::STRING, + defined?(RUBY_ENGINE) ? RUBY_ENGINE : 'ruby', + RUBY_VERSION, RUBY_PATCHLEVEL, RUBY_PLATFORM].join(',') + end end - private - def record_benchmark(test_name, data, measure_mode) - bench_filename = "#{profile_options[:output]}/benchmarks.csv" + protected + HEADER = 'test,metric,measurement,runs,average,created_at,rails_version,ruby_engine,ruby_version,ruby_patchlevel,ruby_platform' - if new_file = !File.exist?(bench_filename) - FileUtils.mkdir_p(File.dirname(bench_filename)) - end + def with_output_file + fname = "#{profile_options[:output]}/benchmarks.csv" - File.open(bench_filename, 'ab') do |file| - if new_file - file.puts 'test,metric,measurement,runs,average,created_at,rails_version,ruby_engine,ruby_version,ruby_patchlevel,ruby_platform' - end + if new = !File.exist?(fname) + FileUtils.mkdir_p(File.dirname(fname)) + end - file.puts [test_name, - ActiveSupport::Testing::Performance::Util.metric_name(measure_mode), - data, profile_options[:runs], data / profile_options[:runs], - Time.now.utc.xmlschema, - Rails::VERSION::STRING, - defined?(RUBY_ENGINE) ? RUBY_ENGINE : 'ruby', - RUBY_VERSION, RUBY_PATCHLEVEL, RUBY_PLATFORM].join(',') + File.open(fname, 'ab') do |file| + file.puts(HEADER) if new + yield file end end + end + + class Profiler < Performer + def run + @runs.times { @harness.run_test(@metric, :profile) } + @data = RubyProf.stop + @total = @data.threads.values.sum(0) { |method_infos| method_infos.sort.last.total_time } + end - def record_profile(test_name, data, measure_mode) - printer_classes.each do |printer_class| - fname = output_filename(test_name, printer_class, measure_mode) + def record(path) + klasses = profile_options[:formats].map { |f| RubyProf.const_get("#{f.to_s.camelize}Printer") }.compact - FileUtils.mkdir_p(File.dirname(fname)) - File.open(fname, 'wb') do |file| - printer_class.new(data).print(file, profile_printer_options) - end + klasses.each do |klass| + fname = output_filename(metric, klass) + FileUtils.mkdir_p(File.dirname(fname)) + File.open(fname, 'wb') do |file| + klass.new(@data).print(file, profile_options.slice(:min_percent)) end end + end - # The report filename is test_name + measure_mode + report_type - def output_filename(test_name, printer_class, measure_mode) + protected + def output_filename(metric, printer_class) suffix = case printer_class.name.demodulize when 'FlatPrinter'; 'flat.txt' @@ -187,39 +160,140 @@ module ActiveSupport else printer_class.name.sub(/Printer$/, '').underscore end - "#{profile_options[:output]}/#{test_name}_#{ActiveSupport::Testing::Performance::Util.metric_name(measure_mode)}_#{suffix}" + "#{profile_options[:output]}/#{full_test_name}_#{metric.name}_#{suffix}" end + end + + module Metrics + def self.[](name) + klass = const_get(name.to_s.camelize) + klass if klass::Mode + rescue + nil + end + + class Base + attr_reader :total - def profile_printer_options - profile_options.slice(:min_percent) + def initialize + @total = 0 + end + + def name + @name ||= self.class.name.demodulize.underscore end - end - module Util - extend self + def benchmark + with_gc_stats do + before = measure + yield + @total += (measure - before) + end + end - def metric_name(measure_mode) - case measure_mode - when RubyProf::PROCESS_TIME; 'process_time' - when RubyProf::WALL_TIME; 'wall_time' - when RubyProf::MEMORY; 'memory' - when RubyProf::ALLOCATIONS; 'allocations' - else "measure#{measure_mode}" + def profile + RubyProf.measure_mode = MODE + RubyProf.resume { yield } end + + protected + if GC.respond_to?(:enable_stats) + def with_gc_stats + GC.enable_stats + yield + ensure + GC.disable_stats + end + else + def with_gc_stats + yield + end + end end - def measure_modes(metrics) - ruby_prof_consts(metrics.map { |m| m.to_s.upcase }) + class Time < Base + def measure + ::Time.now.to_f + end + + def format(measurement) + if measurement < 2 + '%d ms' % (measurement * 1000) + else + '%.2f sec' % measurement + end + end end - def printer_classes(formats) - ruby_prof_consts(formats.map { |f| "#{f.to_s.camelize}Printer" }) + class ProcessTime < Time + Mode = RubyProf::PROCESS_TIME + + def measure + RubyProf.measure_process_time + end end - private - def ruby_prof_consts(names) - names.map { |name| RubyProf.const_get(name) rescue nil }.compact + class WallTime < Time + Mode = RubyProf::WALL_TIME + + def measure + RubyProf.measure_wall_time end + end + + class CpuTime < Time + Mode = RubyProf::CPU_TIME + + def initialize(*args) + # FIXME: yeah my CPU is 2.33 GHz + RubyProf.cpu_frequency = 2.33e9 + super + end + + def measure + RubyProf.measure_cpu_time + end + end + + class Memory < Base + Mode = RubyProf::MEMORY + + if RubyProf.respond_to?(:measure_memory) + def measure + RubyProf.measure_memory + end + elsif GC.respond_to?(:allocated_size) + def measure + GC.allocated_size + end + elsif GC.respond_to?(:malloc_allocated_size) + def measure + GC.malloc_allocated_size + end + end + + def format(measurement) + '%.2f KB' % (measurement / 1024.0) + end + end + + class Objects < Base + Mode = RubyProf::ALLOCATIONS + + if RubyProf.respond_to?(:measure_allocations) + def measure + RubyProf.measure_allocations + end + elsif ObjectSpace.respond_to?(:allocated_objects) + def measure + ObjectSpace.allocated_objects + end + end + + def format(measurement) + measurement.to_s + end + end end end end -- cgit v1.2.3