* transcode.c (transcode_restartable): my_transcoder argument removed.
[ruby-svn.git] / lib / benchmark.rb
bloba54700a1c220212f15b17e44dce3de702365e83c
1 =begin
3 # benchmark.rb - a performance benchmarking library 
4
5 # $Id$
6
7 # Created by Gotoken (gotoken@notwork.org). 
9 # Documentation by Gotoken (original RD), Lyle Johnson (RDoc conversion), and
10 # Gavin Sinclair (editing). 
12 =end
14 # == Overview
16 # The Benchmark module provides methods for benchmarking Ruby code, giving
17 # detailed reports on the time taken for each task.
20 # The Benchmark module provides methods to measure and report the time
21 # used to execute Ruby code.
23 # * Measure the time to construct the string given by the expression
24 #   <tt>"a"*1_000_000</tt>:
26 #       require 'benchmark'
28 #       puts Benchmark.measure { "a"*1_000_000 }
29
30 #   On my machine (FreeBSD 3.2 on P5, 100MHz) this generates:
31
32 #       1.166667   0.050000   1.216667 (  0.571355)
33
34 #   This report shows the user CPU time, system CPU time, the sum of
35 #   the user and system CPU times, and the elapsed real time. The unit
36 #   of time is seconds.
37
38 # * Do some experiments sequentially using the #bm method:
40 #       require 'benchmark'
42 #       n = 50000
43 #       Benchmark.bm do |x|
44 #         x.report { for i in 1..n; a = "1"; end }
45 #         x.report { n.times do   ; a = "1"; end }
46 #         x.report { 1.upto(n) do ; a = "1"; end }
47 #       end
48
49 #   The result:
51 #              user     system      total        real
52 #          1.033333   0.016667   1.016667 (  0.492106)
53 #          1.483333   0.000000   1.483333 (  0.694605)
54 #          1.516667   0.000000   1.516667 (  0.711077)
56 # * Continuing the previous example, put a label in each report:
58 #       require 'benchmark'
60 #       n = 50000
61 #       Benchmark.bm(7) do |x|
62 #         x.report("for:")   { for i in 1..n; a = "1"; end }
63 #         x.report("times:") { n.times do   ; a = "1"; end }
64 #         x.report("upto:")  { 1.upto(n) do ; a = "1"; end }
65 #       end
66
67 # The result:
68
69 #                     user     system      total        real
70 #        for:     1.050000   0.000000   1.050000 (  0.503462)
71 #        times:   1.533333   0.016667   1.550000 (  0.735473)
72 #        upto:    1.500000   0.016667   1.516667 (  0.711239)
73
75 # * The times for some benchmarks depend on the order in which items
76 #   are run.  These differences are due to the cost of memory
77 #   allocation and garbage collection. To avoid these discrepancies,
78 #   the #bmbm method is provided.  For example, to compare ways to
79 #   sort an array of floats:
81 #       require 'benchmark'
82 #       
83 #       array = (1..1000000).map { rand }
84 #       
85 #       Benchmark.bmbm do |x|
86 #         x.report("sort!") { array.dup.sort! }
87 #         x.report("sort")  { array.dup.sort  }
88 #       end
89
90 #   The result:
91
92 #        Rehearsal -----------------------------------------
93 #        sort!  11.928000   0.010000  11.938000 ( 12.756000)
94 #        sort   13.048000   0.020000  13.068000 ( 13.857000)
95 #        ------------------------------- total: 25.006000sec
96 #        
97 #                    user     system      total        real
98 #        sort!  12.959000   0.010000  12.969000 ( 13.793000)
99 #        sort   12.007000   0.000000  12.007000 ( 12.791000)
102 # * Report statistics of sequential experiments with unique labels,
103 #   using the #benchmark method:
105 #       require 'benchmark'
107 #       n = 50000
108 #       Benchmark.benchmark(" "*7 + CAPTION, 7, FMTSTR, ">total:", ">avg:") do |x|
109 #         tf = x.report("for:")   { for i in 1..n; a = "1"; end }
110 #         tt = x.report("times:") { n.times do   ; a = "1"; end }
111 #         tu = x.report("upto:")  { 1.upto(n) do ; a = "1"; end }
112 #         [tf+tt+tu, (tf+tt+tu)/3]
113 #       end
115 #   The result:
117 #                     user     system      total        real
118 #        for:     1.016667   0.016667   1.033333 (  0.485749)
119 #        times:   1.450000   0.016667   1.466667 (  0.681367)
120 #        upto:    1.533333   0.000000   1.533333 (  0.722166)
121 #        >total:  4.000000   0.033333   4.033333 (  1.889282)
122 #        >avg:    1.333333   0.011111   1.344444 (  0.629761)
124 module Benchmark
126   BENCHMARK_VERSION = "2002-04-25" #:nodoc"
128   def Benchmark::times() # :nodoc:
129       Process::times()
130   end
133   # Invokes the block with a <tt>Benchmark::Report</tt> object, which
134   # may be used to collect and report on the results of individual
135   # benchmark tests. Reserves <i>label_width</i> leading spaces for
136   # labels on each line. Prints _caption_ at the top of the
137   # report, and uses _fmt_ to format each line.
138   # If the block returns an array of
139   # <tt>Benchmark::Tms</tt> objects, these will be used to format
140   # additional lines of output. If _label_ parameters are
141   # given, these are used to label these extra lines.
142   #
143   # _Note_: Other methods provide a simpler interface to this one, and are
144   # suitable for nearly all benchmarking requirements.  See the examples in
145   # Benchmark, and the #bm and #bmbm methods.
146   #
147   # Example: 
148   #
149   #     require 'benchmark'
150   #     include Benchmark          # we need the CAPTION and FMTSTR constants 
151   #
152   #     n = 50000
153   #     Benchmark.benchmark(" "*7 + CAPTION, 7, FMTSTR, ">total:", ">avg:") do |x|
154   #       tf = x.report("for:")   { for i in 1..n; a = "1"; end }
155   #       tt = x.report("times:") { n.times do   ; a = "1"; end }
156   #       tu = x.report("upto:")  { 1.upto(n) do ; a = "1"; end }
157   #       [tf+tt+tu, (tf+tt+tu)/3]
158   #     end
159   # 
160   # <i>Generates:</i>
161   # 
162   #                     user     system      total        real
163   #        for:     1.016667   0.016667   1.033333 (  0.485749)
164   #        times:   1.450000   0.016667   1.466667 (  0.681367)
165   #        upto:    1.533333   0.000000   1.533333 (  0.722166)
166   #        >total:  4.000000   0.033333   4.033333 (  1.889282)
167   #        >avg:    1.333333   0.011111   1.344444 (  0.629761)
168   # 
170   def benchmark(caption = "", label_width = nil, fmtstr = nil, *labels) # :yield: report
171     sync = STDOUT.sync
172     STDOUT.sync = true
173     label_width ||= 0
174     fmtstr ||= FMTSTR
175     raise ArgumentError, "no block" unless iterator?
176     print caption
177     results = yield(Report.new(label_width, fmtstr))
178     Array === results and results.grep(Tms).each {|t|
179       print((labels.shift || t.label || "").ljust(label_width), 
180             t.format(fmtstr))
181     }
182     STDOUT.sync = sync
183   end
186   # A simple interface to the #benchmark method, #bm is generates sequential reports
187   # with labels.  The parameters have the same meaning as for #benchmark.
188   # 
189   #     require 'benchmark'
190   #
191   #     n = 50000
192   #     Benchmark.bm(7) do |x|
193   #       x.report("for:")   { for i in 1..n; a = "1"; end }
194   #       x.report("times:") { n.times do   ; a = "1"; end }
195   #       x.report("upto:")  { 1.upto(n) do ; a = "1"; end }
196   #     end
197   # 
198   # <i>Generates:</i>
199   # 
200   #                     user     system      total        real
201   #        for:     1.050000   0.000000   1.050000 (  0.503462)
202   #        times:   1.533333   0.016667   1.550000 (  0.735473)
203   #        upto:    1.500000   0.016667   1.516667 (  0.711239)
204   #
206   def bm(label_width = 0, *labels, &blk) # :yield: report
207     benchmark(" "*label_width + CAPTION, label_width, FMTSTR, *labels, &blk)
208   end
211   # Sometimes benchmark results are skewed because code executed
212   # earlier encounters different garbage collection overheads than
213   # that run later. #bmbm attempts to minimize this effect by running
214   # the tests twice, the first time as a rehearsal in order to get the
215   # runtime environment stable, the second time for
216   # real. <tt>GC.start</tt> is executed before the start of each of
217   # the real timings; the cost of this is not included in the
218   # timings. In reality, though, there's only so much that #bmbm can
219   # do, and the results are not guaranteed to be isolated from garbage
220   # collection and other effects.
221   #
222   # Because #bmbm takes two passes through the tests, it can
223   # calculate the required label width.
224   #
225   #       require 'benchmark'
226   #       
227   #       array = (1..1000000).map { rand }
228   #       
229   #       Benchmark.bmbm do |x|
230   #         x.report("sort!") { array.dup.sort! }
231   #         x.report("sort")  { array.dup.sort  }
232   #       end
233   # 
234   # <i>Generates:</i>
235   # 
236   #        Rehearsal -----------------------------------------
237   #        sort!  11.928000   0.010000  11.938000 ( 12.756000)
238   #        sort   13.048000   0.020000  13.068000 ( 13.857000)
239   #        ------------------------------- total: 25.006000sec
240   #        
241   #                    user     system      total        real
242   #        sort!  12.959000   0.010000  12.969000 ( 13.793000)
243   #        sort   12.007000   0.000000  12.007000 ( 12.791000)
244   #
245   # #bmbm yields a Benchmark::Job object and returns an array of
246   # Benchmark::Tms objects.
247   #
248   def bmbm(width = 0, &blk) # :yield: job
249     job = Job.new(width)
250     yield(job)
251     width = job.width
252     sync = STDOUT.sync
253     STDOUT.sync = true
255     # rehearsal
256     print "Rehearsal "
257     puts '-'*(width+CAPTION.length - "Rehearsal ".length)
258     list = []
259     job.list.each{|label,item|
260       print(label.ljust(width))
261       res = Benchmark::measure(&item)
262       print res.format()
263       list.push res
264     }
265     sum = Tms.new; list.each{|i| sum += i}
266     ets = sum.format("total: %tsec")
267     printf("%s %s\n\n",
268            "-"*(width+CAPTION.length-ets.length-1), ets)
269     
270     # take
271     print ' '*width, CAPTION
272     list = []
273     ary = []
274     job.list.each{|label,item|
275       GC::start
276       print label.ljust(width)
277       res = Benchmark::measure(&item)
278       print res.format()
279       ary.push res
280       list.push [label, res]
281     }
283     STDOUT.sync = sync
284     ary
285   end
287   # 
288   # Returns the time used to execute the given block as a
289   # Benchmark::Tms object.
290   #
291   def measure(label = "") # :yield:
292     t0, r0 = Benchmark.times, Time.now
293     yield
294     t1, r1 = Benchmark.times, Time.now
295     Benchmark::Tms.new(t1.utime  - t0.utime, 
296                        t1.stime  - t0.stime, 
297                        t1.cutime - t0.cutime, 
298                        t1.cstime - t0.cstime, 
299                        r1.to_f - r0.to_f,
300                        label)
301   end
303   #
304   # Returns the elapsed real time used to execute the given block.
305   #
306   def realtime(&blk) # :yield:
307     r0 = Time.now
308     yield
309     r1 = Time.now
310     r1.to_f - r0.to_f
311   end
315   #
316   # A Job is a sequence of labelled blocks to be processed by the
317   # Benchmark.bmbm method.  It is of little direct interest to the user.
318   #
319   class Job # :nodoc:
320     #
321     # Returns an initialized Job instance.
322     # Usually, one doesn't call this method directly, as new
323     # Job objects are created by the #bmbm method.
324     # _width_ is a initial value for the label offset used in formatting;
325     # the #bmbm method passes its _width_ argument to this constructor. 
326     # 
327     def initialize(width)
328       @width = width
329       @list = []
330     end
332     #
333     # Registers the given label and block pair in the job list.
334     #
335     def item(label = "", &blk) # :yield:
336       raise ArgumentError, "no block" unless block_given?
337       label += ' '
338       w = label.length
339       @width = w if @width < w
340       @list.push [label, blk]
341       self
342     end
344     alias report item
345     
346     # An array of 2-element arrays, consisting of label and block pairs.
347     attr_reader :list
348     
349     # Length of the widest label in the #list, plus one.  
350     attr_reader :width
351   end
353   module_function :benchmark, :measure, :realtime, :bm, :bmbm
357   #
358   # This class is used by the Benchmark.benchmark and Benchmark.bm methods.
359   # It is of little direct interest to the user.
360   #
361   class Report # :nodoc:
362     #
363     # Returns an initialized Report instance.
364     # Usually, one doesn't call this method directly, as new
365     # Report objects are created by the #benchmark and #bm methods. 
366     # _width_ and _fmtstr_ are the label offset and 
367     # format string used by Tms#format. 
368     # 
369     def initialize(width = 0, fmtstr = nil)
370       @width, @fmtstr = width, fmtstr
371     end
373     #
374     # Prints the _label_ and measured time for the block,
375     # formatted by _fmt_. See Tms#format for the
376     # formatting rules.
377     #
378     def item(label = "", *fmt, &blk) # :yield:
379       print label.ljust(@width)
380       res = Benchmark::measure(&blk)
381       print res.format(@fmtstr, *fmt)
382       res
383     end
385     alias report item
386   end
390   #
391   # A data object, representing the times associated with a benchmark
392   # measurement.
393   #
394   class Tms
395     CAPTION = "      user     system      total        real\n"
396     FMTSTR = "%10.6u %10.6y %10.6t %10.6r\n"
398     # User CPU time
399     attr_reader :utime
400     
401     # System CPU time
402     attr_reader :stime
403    
404     # User CPU time of children
405     attr_reader :cutime
406     
407     # System CPU time of children
408     attr_reader :cstime
409     
410     # Elapsed real time
411     attr_reader :real
412     
413     # Total time, that is _utime_ + _stime_ + _cutime_ + _cstime_ 
414     attr_reader :total
415     
416     # Label
417     attr_reader :label
419     #
420     # Returns an initialized Tms object which has
421     # _u_ as the user CPU time, _s_ as the system CPU time, 
422     # _cu_ as the children's user CPU time, _cs_ as the children's
423     # system CPU time, _real_ as the elapsed real time and _l_
424     # as the label. 
425     # 
426     def initialize(u = 0.0, s = 0.0, cu = 0.0, cs = 0.0, real = 0.0, l = nil)
427       @utime, @stime, @cutime, @cstime, @real, @label = u, s, cu, cs, real, l
428       @total = @utime + @stime + @cutime + @cstime
429     end
431     # 
432     # Returns a new Tms object whose times are the sum of the times for this
433     # Tms object, plus the time required to execute the code block (_blk_).
434     # 
435     def add(&blk) # :yield:
436       self + Benchmark::measure(&blk) 
437     end
439     # 
440     # An in-place version of #add.
441     # 
442     def add!
443       t = Benchmark::measure(&blk) 
444       @utime  = utime + t.utime
445       @stime  = stime + t.stime
446       @cutime = cutime + t.cutime
447       @cstime = cstime + t.cstime
448       @real   = real + t.real
449       self
450     end
452     # 
453     # Returns a new Tms object obtained by memberwise summation
454     # of the individual times for this Tms object with those of the other
455     # Tms object.
456     # This method and #/() are useful for taking statistics. 
457     # 
458     def +(other); memberwise(:+, other) end
459     
460     #
461     # Returns a new Tms object obtained by memberwise subtraction
462     # of the individual times for the other Tms object from those of this
463     # Tms object.
464     #
465     def -(other); memberwise(:-, other) end
466     
467     #
468     # Returns a new Tms object obtained by memberwise multiplication
469     # of the individual times for this Tms object by _x_.
470     #
471     def *(x); memberwise(:*, x) end
473     # 
474     # Returns a new Tms object obtained by memberwise division
475     # of the individual times for this Tms object by _x_.
476     # This method and #+() are useful for taking statistics. 
477     # 
478     def /(x); memberwise(:/, x) end
480     #
481     # Returns the contents of this Tms object as
482     # a formatted string, according to a format string
483     # like that passed to Kernel.format. In addition, #format
484     # accepts the following extensions:
485     #
486     # <tt>%u</tt>::     Replaced by the user CPU time, as reported by Tms#utime.
487     # <tt>%y</tt>::     Replaced by the system CPU time, as reported by #stime (Mnemonic: y of "s*y*stem")
488     # <tt>%U</tt>::     Replaced by the children's user CPU time, as reported by Tms#cutime 
489     # <tt>%Y</tt>::     Replaced by the children's system CPU time, as reported by Tms#cstime
490     # <tt>%t</tt>::     Replaced by the total CPU time, as reported by Tms#total
491     # <tt>%r</tt>::     Replaced by the elapsed real time, as reported by Tms#real
492     # <tt>%n</tt>::     Replaced by the label string, as reported by Tms#label (Mnemonic: n of "*n*ame")
493     # 
494     # If _fmtstr_ is not given, FMTSTR is used as default value, detailing the
495     # user, system and real elapsed time.
496     # 
497     def format(arg0 = nil, *args)
498       fmtstr = (arg0 || FMTSTR).dup
499       fmtstr.gsub!(/(%[-+\.\d]*)n/){"#{$1}s" % label}
500       fmtstr.gsub!(/(%[-+\.\d]*)u/){"#{$1}f" % utime}
501       fmtstr.gsub!(/(%[-+\.\d]*)y/){"#{$1}f" % stime}
502       fmtstr.gsub!(/(%[-+\.\d]*)U/){"#{$1}f" % cutime}
503       fmtstr.gsub!(/(%[-+\.\d]*)Y/){"#{$1}f" % cstime}
504       fmtstr.gsub!(/(%[-+\.\d]*)t/){"#{$1}f" % total}
505       fmtstr.gsub!(/(%[-+\.\d]*)r/){"(#{$1}f)" % real}
506       arg0 ? Kernel::format(fmtstr, *args) : fmtstr
507     end
509     # 
510     # Same as #format.
511     # 
512     def to_s
513       format
514     end
516     # 
517     # Returns a new 6-element array, consisting of the
518     # label, user CPU time, system CPU time, children's
519     # user CPU time, children's system CPU time and elapsed
520     # real time.
521     # 
522     def to_a
523       [@label, @utime, @stime, @cutime, @cstime, @real]
524     end
526     protected
527     def memberwise(op, x)
528       case x
529       when Benchmark::Tms
530         Benchmark::Tms.new(utime.__send__(op, x.utime),
531                            stime.__send__(op, x.stime),
532                            cutime.__send__(op, x.cutime),
533                            cstime.__send__(op, x.cstime),
534                            real.__send__(op, x.real)
535                            )
536       else
537         Benchmark::Tms.new(utime.__send__(op, x),
538                            stime.__send__(op, x),
539                            cutime.__send__(op, x),
540                            cstime.__send__(op, x),
541                            real.__send__(op, x)
542                            )
543       end
544     end
545   end
547   # The default caption string (heading above the output times).
548   CAPTION = Benchmark::Tms::CAPTION
550   # The default format string used to display times.  See also Benchmark::Tms#format. 
551   FMTSTR = Benchmark::Tms::FMTSTR
554 if __FILE__ == $0
555   include Benchmark
557   n = ARGV[0].to_i.nonzero? || 50000
558   puts %Q([#{n} times iterations of `a = "1"'])
559   benchmark("       " + CAPTION, 7, FMTSTR) do |x|
560     x.report("for:")   {for i in 1..n; a = "1"; end} # Benchmark::measure
561     x.report("times:") {n.times do   ; a = "1"; end}
562     x.report("upto:")  {1.upto(n) do ; a = "1"; end}
563   end
565   benchmark do
566     [
567       measure{for i in 1..n; a = "1"; end},  # Benchmark::measure
568       measure{n.times do   ; a = "1"; end},
569       measure{1.upto(n) do ; a = "1"; end}
570     ]
571   end