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