lib/benchmark.rb

   1 =begin
   2 #
   3 # benchmark.rb - a performance benchmarking library
   4 #
   5 # $Id$
   6 #
   7 # Created by Gotoken (gotoken@notwork.org).
   8 #
   9 # Documentation by Gotoken (original RD), Lyle Johnson (RDoc conversion), and
  10 # Gavin Sinclair (editing).
  11 #
  12 =end
  13
  14 # == Overview
  15 #
  16 # The Benchmark module provides methods for benchmarking Ruby code, giving
  17 # detailed reports on the time taken for each task.
  18 #
  19
  20 # The Benchmark module provides methods to measure and report the time
  21 # used to execute Ruby code.
  22 #
  23 # * Measure the time to construct the string given by the expression
  24 #   <tt>"a"*1_000_000</tt>:
  25 #
  26 #       require 'benchmark'
  27 #
  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:
  39 #
  40 #       require 'benchmark'
  41 #
  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:
  50 #
  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)
  55 #
  56 # * Continuing the previous example, put a label in each report:
  57 #
  58 #       require 'benchmark'
  59 #
  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 #
  74 #
  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:
  80 #
  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)
 100 #
 101 #
 102 # * Report statistics of sequential experiments with unique labels,
 103 #   using the #benchmark method:
 104 #
 105 #       require 'benchmark'
 106 #
 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
 114 #
 115 #   The result:
 116 #
 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)
 123
 124 module Benchmark
 125
 126   BENCHMARK_VERSION = "2002-04-25" #:nodoc"
 127
 128   def Benchmark::times() # :nodoc:
 129       Process::times()
 130   end
 131
 132
 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   #
 169
 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
 184
 185
 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   #
 205
 206   def bm(label_width = 0, *labels, &blk) # :yield: report
 207     benchmark(" "*label_width + CAPTION, label_width, FMTSTR, *labels, &blk)
 208   end
 209
 210
 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
 254
 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     }
 282
 283     STDOUT.sync = sync
 284     ary
 285   end
 286
 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
 302
 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
 312
 313
 314
 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
 331
 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
 343
 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
 352
 353   module_function :benchmark, :measure, :realtime, :bm, :bmbm
 354
 355
 356
 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
 372
 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
 384
 385     alias report item
 386   end
 387
 388
 389
 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"
 397
 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
 418
 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
 430
 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
 438
 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
 451
 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
 472
 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
 479
 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
 508
 509     #
 510     # Same as #format.
 511     #
 512     def to_s
 513       format
 514     end
 515
 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
 525
 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
 546
 547   # The default caption string (heading above the output times).
 548   CAPTION = Benchmark::Tms::CAPTION
 549
 550   # The default format string used to display times.  See also Benchmark::Tms#format.
 551   FMTSTR = Benchmark::Tms::FMTSTR
 552 end
 553
 554 if __FILE__ == $0
 555   include Benchmark
 556
 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
 564
 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
 572 end