1 require 'rubygems'
2 gem 'ruby-prof', '>= 0.6.1'
3 require 'ruby-prof'
4
5 require 'fileutils'
6 require 'rails/version'
7
8 module ActiveSupport
9 module Testing
10 module Performance
11 DEFAULTS =
12 if benchmark = ARGV.include?('--benchmark') # HAX for rake test
13 { :benchmark => true,
14 :runs => 4,
15 :metrics => [:wall_time, :memory, :objects, :gc_runs, :gc_time],
16 :output => 'tmp/performance' }
17 else
18 { :benchmark => false,
19 :runs => 1,
20 :min_percent => 0.01,
21 :metrics => [:process_time, :memory, :objects],
22 :formats => [:flat, :graph_html, :call_tree],
23 :output => 'tmp/performance' }
24 end.freeze
25
26 def self.included(base)
27 base.class_attribute :profile_options
28 base.profile_options = DEFAULTS
29 end
30
31 def full_test_name
32 "#{self.class.name}##{method_name}"
33 end
34
35 def run(result)
36 return if method_name =~ /^default_test$/
37
38 yield(self.class::STARTED, name)
39 @_result = result
40
41 run_warmup
42 if profile_options && metrics = profile_options[:metrics]
43 metrics.each do |metric_name|
44 if klass = Metrics[metric_name.to_sym]
45 run_profile(klass.new)
46 result.add_run
47 end
48 end
49 end
50
51 yield(self.class::FINISHED, name)
52 end
53
54 def run_test(metric, mode)
55 run_callbacks :setup
56 setup
57 metric.send(mode) { __send__ @method_name }
58 rescue ::Test::Unit::AssertionFailedError => e
59 add_failure(e.message, e.backtrace)
60 rescue StandardError, ScriptError
61 add_error($!)
62 ensure
63 begin
64 teardown
65 run_callbacks :teardown, :enumerator => :reverse_each
66 rescue ::Test::Unit::AssertionFailedError => e
67 add_failure(e.message, e.backtrace)
68 rescue StandardError, ScriptError
69 add_error($!)
70 end
71 end
72
73 protected
74 def run_warmup
75 GC.start
76
77 time = Metrics::Time.new
78 run_test(time, :benchmark)
79 puts "%s (%s warmup)" % [full_test_name, time.format(time.total)]
80
81 GC.start
82 end
83
84 def run_profile(metric)
85 klass = profile_options[:benchmark] ? Benchmarker : Profiler
86 performer = klass.new(self, metric)
87
88 performer.run
89 puts performer.report
90 performer.record
91 end
92
93 class Performer
94 delegate :run_test, :profile_options, :full_test_name, :to => :@harness
95
96 def initialize(harness, metric)
97 @harness, @metric = harness, metric
98 end
99
100 def report
101 rate = @total / profile_options[:runs]
102 '%20s: %s' % [@metric.name, @metric.format(rate)]
103 end
104
105 protected
106 def output_filename
107 "#{profile_options[:output]}/#{full_test_name}_#{@metric.name}"
108 end
109 end
110
111 class Benchmarker < Performer
112 def run
113 profile_options[:runs].to_i.times { run_test(@metric, :benchmark) }
114 @total = @metric.total
115 end
116
117 def record
118 avg = @metric.total / profile_options[:runs].to_i
119 now = Time.now.utc.xmlschema
120 with_output_file do |file|
121 file.puts "#{avg},#{now},#{environment}"
122 end
123 end
124
125 def environment
126 unless defined? @env
127 app = "#{$1}.#{$2}" if File.directory?('.git') && `git branch -v` =~ /^\* (\S+)\s+(\S+)/
128
129 rails = Rails::VERSION::STRING
130 if File.directory?('vendor/rails/.git')
131 Dir.chdir('vendor/rails') do
132 rails += ".#{$1}.#{$2}" if `git branch -v` =~ /^\* (\S+)\s+(\S+)/
133 end
134 end
135
136 ruby = defined?(RUBY_ENGINE) ? RUBY_ENGINE : 'ruby'
137 ruby += "-#{RUBY_VERSION}.#{RUBY_PATCHLEVEL}"
138
139 @env = [app, rails, ruby, RUBY_PLATFORM] * ','
140 end
141
142 @env
143 end
144
145 protected
146 HEADER = 'measurement,created_at,app,rails,ruby,platform'
147
148 def with_output_file
149 fname = output_filename
150
151 if new = !File.exist?(fname)
152 FileUtils.mkdir_p(File.dirname(fname))
153 end
154
155 File.open(fname, 'ab') do |file|
156 file.puts(HEADER) if new
157 yield file
158 end
159 end
160
161 def output_filename
162 "#{super}.csv"
163 end
164 end
165
166 class Profiler < Performer
167 def initialize(*args)
168 super
169 @supported = @metric.measure_mode rescue false
170 end
171
172 def run
173 return unless @supported
174
175 RubyProf.measure_mode = @metric.measure_mode
176 RubyProf.start
177 RubyProf.pause
178 profile_options[:runs].to_i.times { run_test(@metric, :profile) }
179 @data = RubyProf.stop
180 @total = @data.threads.values.sum(0) { |method_infos| method_infos.sort.last.total_time }
181 end
182
183 def report
184 if @supported
185 super
186 else
187 '%20s: unsupported' % @metric.name
188 end
189 end
190
191 def record
192 return unless @supported
193
194 klasses = profile_options[:formats].map { |f| RubyProf.const_get("#{f.to_s.camelize}Printer") }.compact
195
196 klasses.each do |klass|
197 fname = output_filename(klass)
198 FileUtils.mkdir_p(File.dirname(fname))
199 File.open(fname, 'wb') do |file|
200 klass.new(@data).print(file, profile_options.slice(:min_percent))
201 end
202 end
203 end
204
205 protected
206 def output_filename(printer_class)
207 suffix =
208 case printer_class.name.demodulize
209 when 'FlatPrinter'; 'flat.txt'
210 when 'GraphPrinter'; 'graph.txt'
211 when 'GraphHtmlPrinter'; 'graph.html'
212 when 'CallTreePrinter'; 'tree.txt'
213 else printer_class.name.sub(/Printer$/, '').underscore
214 end
215
216 "#{super()}_#{suffix}"
217 end
218 end
219
220 module Metrics
221 def self.[](name)
222 const_get(name.to_s.camelize)
223 rescue NameError
224 nil
225 end
226
227 class Base
228 attr_reader :total
229
230 def initialize
231 @total = 0
232 end
233
234 def name
235 @name ||= self.class.name.demodulize.underscore
236 end
237
238 def measure_mode
239 self.class::Mode
240 end
241
242 def measure
243 0
244 end
245
246 def benchmark
247 with_gc_stats do
248 before = measure
249 yield
250 @total += (measure - before)
251 end
252 end
253
254 def profile
255 RubyProf.resume
256 yield
257 ensure
258 RubyProf.pause
259 end
260
261 protected
262 if GC.respond_to?(:enable_stats)
263 def with_gc_stats
264 GC.enable_stats
265 yield
266 ensure
267 GC.disable_stats
268 end
269 elsif defined?(GC::Profiler)
270 def with_gc_stats
271 GC.start
272 GC.disable
273 GC::Profiler.enable
274 yield
275 ensure
276 GC::Profiler.disable
277 GC.enable
278 end
279 else
280 def with_gc_stats
281 yield
282 end
283 end
284 end
285
286 class Time < Base
287 def measure
288 ::Time.now.to_f
289 end
290
291 def format(measurement)
292 if measurement < 2
293 '%d ms' % (measurement * 1000)
294 else
295 '%.2f sec' % measurement
296 end
297 end
298 end
299
300 class ProcessTime < Time
301 Mode = RubyProf::PROCESS_TIME
302
303 def measure
304 RubyProf.measure_process_time
305 end
306 end
307
308 class WallTime < Time
309 Mode = RubyProf::WALL_TIME
310
311 def measure
312 RubyProf.measure_wall_time
313 end
314 end
315
316 class CpuTime < Time
317 Mode = RubyProf::CPU_TIME if RubyProf.const_defined?(:CPU_TIME)
318
319 def initialize(*args)
320 # FIXME: yeah my CPU is 2.33 GHz
321 RubyProf.cpu_frequency = 2.33e9
322 super
323 end
324
325 def measure
326 RubyProf.measure_cpu_time
327 end
328 end
329
330 class Memory < Base
331 Mode = RubyProf::MEMORY if RubyProf.const_defined?(:MEMORY)
332
333 # ruby-prof wrapper
334 if RubyProf.respond_to?(:measure_memory)
335 def measure
336 RubyProf.measure_memory / 1024.0
337 end
338
339 # Ruby 1.8 + railsbench patch
340 elsif GC.respond_to?(:allocated_size)
341 def measure
342 GC.allocated_size / 1024.0
343 end
344
345 # Ruby 1.8 + lloyd patch
346 elsif GC.respond_to?(:heap_info)
347 def measure
348 GC.heap_info['heap_current_memory'] / 1024.0
349 end
350
351 # Ruby 1.9 with total_malloc_allocated_size patch
352 elsif GC.respond_to?(:malloc_total_allocated_size)
353 def measure
354 GC.total_malloc_allocated_size / 1024.0
355 end
356
357 # Ruby 1.9 unpatched
358 elsif GC.respond_to?(:malloc_allocated_size)
359 def measure
360 GC.malloc_allocated_size / 1024.0
361 end
362
363 # Ruby 1.9 + GC profiler patch
364 elsif defined?(GC::Profiler)
365 def measure
366 GC.enable
367 GC.start
368 kb = GC::Profiler.data.last[:HEAP_USE_SIZE] / 1024.0
369 GC.disable
370 kb
371 end
372 end
373
374 def format(measurement)
375 '%.2f KB' % measurement
376 end
377 end
378
379 class Objects < Base
380 Mode = RubyProf::ALLOCATIONS if RubyProf.const_defined?(:ALLOCATIONS)
381
382 if RubyProf.respond_to?(:measure_allocations)
383 def measure
384 RubyProf.measure_allocations
385 end
386
387 # Ruby 1.8 + railsbench patch
388 elsif ObjectSpace.respond_to?(:allocated_objects)
389 def measure
390 ObjectSpace.allocated_objects
391 end
392
393 # Ruby 1.9 + GC profiler patch
394 elsif defined?(GC::Profiler)
395 def measure
396 GC.enable
397 GC.start
398 last = GC::Profiler.data.last
399 count = last[:HEAP_LIVE_OBJECTS] + last[:HEAP_FREE_OBJECTS]
400 GC.disable
401 count
402 end
403 end
404
405 def format(measurement)
406 measurement.to_i.to_s
407 end
408 end
409
410 class GcRuns < Base
411 Mode = RubyProf::GC_RUNS if RubyProf.const_defined?(:GC_RUNS)
412
413 if RubyProf.respond_to?(:measure_gc_runs)
414 def measure
415 RubyProf.measure_gc_runs
416 end
417 elsif GC.respond_to?(:collections)
418 def measure
419 GC.collections
420 end
421 elsif GC.respond_to?(:heap_info)
422 def measure
423 GC.heap_info['num_gc_passes']
424 end
425 end
426
427 def format(measurement)
428 measurement.to_i.to_s
429 end
430 end
431
432 class GcTime < Base
433 Mode = RubyProf::GC_TIME if RubyProf.const_defined?(:GC_TIME)
434
435 if RubyProf.respond_to?(:measure_gc_time)
436 def measure
437 RubyProf.measure_gc_time
438 end
439 elsif GC.respond_to?(:time)
440 def measure
441 GC.time
442 end
443 end
444
445 def format(measurement)
446 '%d ms' % (measurement / 1000)
447 end
448 end
449 end
450 end
451 end
452 end