src/testing/benchmark.go

   1 // Copyright 2009 The Go Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style
   3 // license that can be found in the LICENSE file.
   4
   5 package testing
   6
   7 import (
   8         "flag"
   9         "fmt"
  10         "os"
  11         "runtime"
  12         "sync"
  13         "sync/atomic"
  14         "time"
  15 )
  16
  17 var matchBenchmarks = flag.String("test.bench", "", "regular expression to select benchmarks to run")
  18 var benchTime = flag.Duration("test.benchtime", 1*time.Second, "approximate run time for each benchmark")
  19 var benchmarkMemory = flag.Bool("test.benchmem", false, "print memory allocations for benchmarks")
  20
  21 // Global lock to ensure only one benchmark runs at a time.
  22 var benchmarkLock sync.Mutex
  23
  24 // Used for every benchmark for measuring memory.
  25 var memStats runtime.MemStats
  26
  27 // An internal type but exported because it is cross-package; part of the implementation
  28 // of the "go test" command.
  29 type InternalBenchmark struct {
  30         Name string
  31         F    func(b *B)
  32 }
  33
  34 // B is a type passed to Benchmark functions to manage benchmark
  35 // timing and to specify the number of iterations to run.
  36 //
  37 // A benchmark ends when its Benchmark function returns or calls any of the methods
  38 // FailNow, Fatal, Fatalf, SkipNow, Skip, or Skipf. Those methods must be called
  39 // only from the goroutine running the Benchmark function.
  40 // The other reporting methods, such as the variations of Log and Error,
  41 // may be called simultaneously from multiple goroutines.
  42 //
  43 // Like in tests, benchmark logs are accumulated during execution
  44 // and dumped to standard error when done. Unlike in tests, benchmark logs
  45 // are always printed, so as not to hide output whose existence may be
  46 // affecting benchmark results.
  47 type B struct {
  48         common
  49         context          *benchContext
  50         N                int
  51         previousN        int           // number of iterations in the previous run
  52         previousDuration time.Duration // total duration of the previous run
  53         benchFunc        func(b *B)
  54         benchTime        time.Duration
  55         bytes            int64
  56         missingBytes     bool // one of the subbenchmarks does not have bytes set.
  57         timerOn          bool
  58         showAllocResult  bool
  59         hasSub           bool
  60         result           BenchmarkResult
  61         parallelism      int // RunParallel creates parallelism*GOMAXPROCS goroutines
  62         // The initial states of memStats.Mallocs and memStats.TotalAlloc.
  63         startAllocs uint64
  64         startBytes  uint64
  65         // The net total of this test after being run.
  66         netAllocs uint64
  67         netBytes  uint64
  68 }
  69
  70 // StartTimer starts timing a test. This function is called automatically
  71 // before a benchmark starts, but it can also used to resume timing after
  72 // a call to StopTimer.
  73 func (b *B) StartTimer() {
  74         if !b.timerOn {
  75                 runtime.ReadMemStats(&memStats)
  76                 b.startAllocs = memStats.Mallocs
  77                 b.startBytes = memStats.TotalAlloc
  78                 b.start = time.Now()
  79                 b.timerOn = true
  80         }
  81 }
  82
  83 // StopTimer stops timing a test. This can be used to pause the timer
  84 // while performing complex initialization that you don't
  85 // want to measure.
  86 func (b *B) StopTimer() {
  87         if b.timerOn {
  88                 b.duration += time.Now().Sub(b.start)
  89                 runtime.ReadMemStats(&memStats)
  90                 b.netAllocs += memStats.Mallocs - b.startAllocs
  91                 b.netBytes += memStats.TotalAlloc - b.startBytes
  92                 b.timerOn = false
  93         }
  94 }
  95
  96 // ResetTimer zeros the elapsed benchmark time and memory allocation counters.
  97 // It does not affect whether the timer is running.
  98 func (b *B) ResetTimer() {
  99         if b.timerOn {
 100                 runtime.ReadMemStats(&memStats)
 101                 b.startAllocs = memStats.Mallocs
 102                 b.startBytes = memStats.TotalAlloc
 103                 b.start = time.Now()
 104         }
 105         b.duration = 0
 106         b.netAllocs = 0
 107         b.netBytes = 0
 108 }
 109
 110 // SetBytes records the number of bytes processed in a single operation.
 111 // If this is called, the benchmark will report ns/op and MB/s.
 112 func (b *B) SetBytes(n int64) { b.bytes = n }
 113
 114 // ReportAllocs enables malloc statistics for this benchmark.
 115 // It is equivalent to setting -test.benchmem, but it only affects the
 116 // benchmark function that calls ReportAllocs.
 117 func (b *B) ReportAllocs() {
 118         b.showAllocResult = true
 119 }
 120
 121 func (b *B) nsPerOp() int64 {
 122         if b.N <= 0 {
 123                 return 0
 124         }
 125         return b.duration.Nanoseconds() / int64(b.N)
 126 }
 127
 128 // runN runs a single benchmark for the specified number of iterations.
 129 func (b *B) runN(n int) {
 130         benchmarkLock.Lock()
 131         defer benchmarkLock.Unlock()
 132         // Try to get a comparable environment for each run
 133         // by clearing garbage from previous runs.
 134         runtime.GC()
 135         b.N = n
 136         b.parallelism = 1
 137         b.ResetTimer()
 138         b.StartTimer()
 139         b.benchFunc(b)
 140         b.StopTimer()
 141         b.previousN = n
 142         b.previousDuration = b.duration
 143 }
 144
 145 func min(x, y int) int {
 146         if x > y {
 147                 return y
 148         }
 149         return x
 150 }
 151
 152 func max(x, y int) int {
 153         if x < y {
 154                 return y
 155         }
 156         return x
 157 }
 158
 159 // roundDown10 rounds a number down to the nearest power of 10.
 160 func roundDown10(n int) int {
 161         var tens = 0
 162         // tens = floor(log_10(n))
 163         for n >= 10 {
 164                 n = n / 10
 165                 tens++
 166         }
 167         // result = 10^tens
 168         result := 1
 169         for i := 0; i < tens; i++ {
 170                 result *= 10
 171         }
 172         return result
 173 }
 174
 175 // roundUp rounds x up to a number of the form [1eX, 2eX, 3eX, 5eX].
 176 func roundUp(n int) int {
 177         base := roundDown10(n)
 178         switch {
 179         case n <= base:
 180                 return base
 181         case n <= (2 * base):
 182                 return 2 * base
 183         case n <= (3 * base):
 184                 return 3 * base
 185         case n <= (5 * base):
 186                 return 5 * base
 187         default:
 188                 return 10 * base
 189         }
 190 }
 191
 192 // probe runs benchFunc to examine if it has any subbenchmarks.
 193 func (b *B) probe() {
 194         if ctx := b.context; ctx != nil {
 195                 // Extend maxLen, if needed.
 196                 if n := len(b.name) + ctx.extLen + 1; n > ctx.maxLen {
 197                         ctx.maxLen = n + 8 // Add additional slack to avoid too many jumps in size.
 198                 }
 199         }
 200         go func() {
 201                 // Signal that we're done whether we return normally
 202                 // or by FailNow's runtime.Goexit.
 203                 defer func() {
 204                         b.signal <- true
 205                 }()
 206
 207                 benchmarkLock.Lock()
 208                 defer benchmarkLock.Unlock()
 209
 210                 b.N = 0
 211                 b.benchFunc(b)
 212         }()
 213         <-b.signal
 214 }
 215
 216 // run executes the benchmark in a separate goroutine, including all of its
 217 // subbenchmarks.
 218 func (b *B) run() BenchmarkResult {
 219         if b.context != nil {
 220                 // Running go test --test.bench
 221                 b.context.processBench(b) // Must call doBench.
 222         } else {
 223                 // Running func Benchmark.
 224                 b.doBench()
 225         }
 226         return b.result
 227 }
 228
 229 func (b *B) doBench() BenchmarkResult {
 230         go b.launch()
 231         <-b.signal
 232         return b.result
 233 }
 234
 235 // launch launches the benchmark function. It gradually increases the number
 236 // of benchmark iterations until the benchmark runs for the requested benchtime.
 237 // launch is run by the doBench function as a separate goroutine.
 238 func (b *B) launch() {
 239         // Run the benchmark for a single iteration in case it's expensive.
 240         n := 1
 241
 242         // Signal that we're done whether we return normally
 243         // or by FailNow's runtime.Goexit.
 244         defer func() {
 245                 b.signal <- true
 246         }()
 247
 248         b.runN(n)
 249         // Run the benchmark for at least the specified amount of time.
 250         d := b.benchTime
 251         for !b.failed && b.duration < d && n < 1e9 {
 252                 last := n
 253                 // Predict required iterations.
 254                 if b.nsPerOp() == 0 {
 255                         n = 1e9
 256                 } else {
 257                         n = int(d.Nanoseconds() / b.nsPerOp())
 258                 }
 259                 // Run more iterations than we think we'll need (1.2x).
 260                 // Don't grow too fast in case we had timing errors previously.
 261                 // Be sure to run at least one more than last time.
 262                 n = max(min(n+n/5, 100*last), last+1)
 263                 // Round up to something easy to read.
 264                 n = roundUp(n)
 265                 b.runN(n)
 266         }
 267         b.result = BenchmarkResult{b.N, b.duration, b.bytes, b.netAllocs, b.netBytes}
 268 }
 269
 270 // The results of a benchmark run.
 271 type BenchmarkResult struct {
 272         N         int           // The number of iterations.
 273         T         time.Duration // The total time taken.
 274         Bytes     int64         // Bytes processed in one iteration.
 275         MemAllocs uint64        // The total number of memory allocations.
 276         MemBytes  uint64        // The total number of bytes allocated.
 277 }
 278
 279 func (r BenchmarkResult) NsPerOp() int64 {
 280         if r.N <= 0 {
 281                 return 0
 282         }
 283         return r.T.Nanoseconds() / int64(r.N)
 284 }
 285
 286 func (r BenchmarkResult) mbPerSec() float64 {
 287         if r.Bytes <= 0 || r.T <= 0 || r.N <= 0 {
 288                 return 0
 289         }
 290         return (float64(r.Bytes) * float64(r.N) / 1e6) / r.T.Seconds()
 291 }
 292
 293 func (r BenchmarkResult) AllocsPerOp() int64 {
 294         if r.N <= 0 {
 295                 return 0
 296         }
 297         return int64(r.MemAllocs) / int64(r.N)
 298 }
 299
 300 func (r BenchmarkResult) AllocedBytesPerOp() int64 {
 301         if r.N <= 0 {
 302                 return 0
 303         }
 304         return int64(r.MemBytes) / int64(r.N)
 305 }
 306
 307 func (r BenchmarkResult) String() string {
 308         mbs := r.mbPerSec()
 309         mb := ""
 310         if mbs != 0 {
 311                 mb = fmt.Sprintf("\t%7.2f MB/s", mbs)
 312         }
 313         nsop := r.NsPerOp()
 314         ns := fmt.Sprintf("%10d ns/op", nsop)
 315         if r.N > 0 && nsop < 100 {
 316                 // The format specifiers here make sure that
 317                 // the ones digits line up for all three possible formats.
 318                 if nsop < 10 {
 319                         ns = fmt.Sprintf("%13.2f ns/op", float64(r.T.Nanoseconds())/float64(r.N))
 320                 } else {
 321                         ns = fmt.Sprintf("%12.1f ns/op", float64(r.T.Nanoseconds())/float64(r.N))
 322                 }
 323         }
 324         return fmt.Sprintf("%8d\t%s%s", r.N, ns, mb)
 325 }
 326
 327 func (r BenchmarkResult) MemString() string {
 328         return fmt.Sprintf("%8d B/op\t%8d allocs/op",
 329                 r.AllocedBytesPerOp(), r.AllocsPerOp())
 330 }
 331
 332 // benchmarkName returns full name of benchmark including procs suffix.
 333 func benchmarkName(name string, n int) string {
 334         if n != 1 {
 335                 return fmt.Sprintf("%s-%d", name, n)
 336         }
 337         return name
 338 }
 339
 340 type benchContext struct {
 341         match *matcher
 342
 343         maxLen int // The largest recorded benchmark name.
 344         extLen int // Maximum extension length.
 345 }
 346
 347 // An internal function but exported because it is cross-package; part of the implementation
 348 // of the "go test" command.
 349 func RunBenchmarks(matchString func(pat, str string) (bool, error), benchmarks []InternalBenchmark) {
 350         runBenchmarksInternal(matchString, benchmarks)
 351 }
 352
 353 func runBenchmarksInternal(matchString func(pat, str string) (bool, error), benchmarks []InternalBenchmark) bool {
 354         // If no flag was specified, don't run benchmarks.
 355         if len(*matchBenchmarks) == 0 {
 356                 return true
 357         }
 358         // Collect matching benchmarks and determine longest name.
 359         maxprocs := 1
 360         for _, procs := range cpuList {
 361                 if procs > maxprocs {
 362                         maxprocs = procs
 363                 }
 364         }
 365         ctx := &benchContext{
 366                 match:  newMatcher(matchString, *matchBenchmarks, "-test.bench"),
 367                 extLen: len(benchmarkName("", maxprocs)),
 368         }
 369         var bs []InternalBenchmark
 370         for _, Benchmark := range benchmarks {
 371                 if _, matched := ctx.match.fullName(nil, Benchmark.Name); matched {
 372                         bs = append(bs, Benchmark)
 373                         benchName := benchmarkName(Benchmark.Name, maxprocs)
 374                         if l := len(benchName) + ctx.extLen + 1; l > ctx.maxLen {
 375                                 ctx.maxLen = l
 376                         }
 377                 }
 378         }
 379         main := &B{
 380                 common: common{name: "Main"},
 381                 benchFunc: func(b *B) {
 382                         for _, Benchmark := range bs {
 383                                 b.runBench(Benchmark.Name, Benchmark.F)
 384                         }
 385                 },
 386                 benchTime: *benchTime,
 387                 context:   ctx,
 388         }
 389         main.runN(1)
 390         return !main.failed
 391 }
 392
 393 // processBench runs bench b for the configured CPU counts and prints the results.
 394 func (ctx *benchContext) processBench(b *B) {
 395         for _, procs := range cpuList {
 396                 runtime.GOMAXPROCS(procs)
 397                 benchName := benchmarkName(b.name, procs)
 398                 b := &B{
 399                         common: common{
 400                                 signal: make(chan bool),
 401                                 name:   benchName,
 402                         },
 403                         benchFunc: b.benchFunc,
 404                         benchTime: b.benchTime,
 405                 }
 406                 fmt.Printf("%-*s\t", ctx.maxLen, benchName)
 407                 r := b.doBench()
 408                 if b.failed {
 409                         // The output could be very long here, but probably isn't.
 410                         // We print it all, regardless, because we don't want to trim the reason
 411                         // the benchmark failed.
 412                         fmt.Printf("--- FAIL: %s\n%s", benchName, b.output)
 413                         continue
 414                 }
 415                 results := r.String()
 416                 if *benchmarkMemory || b.showAllocResult {
 417                         results += "\t" + r.MemString()
 418                 }
 419                 fmt.Println(results)
 420                 // Unlike with tests, we ignore the -chatty flag and always print output for
 421                 // benchmarks since the output generation time will skew the results.
 422                 if len(b.output) > 0 {
 423                         b.trimOutput()
 424                         fmt.Printf("--- BENCH: %s\n%s", benchName, b.output)
 425                 }
 426                 if p := runtime.GOMAXPROCS(-1); p != procs {
 427                         fmt.Fprintf(os.Stderr, "testing: %s left GOMAXPROCS set to %d\n", benchName, p)
 428                 }
 429         }
 430 }
 431
 432 // runBench benchmarks f as a subbenchmark with the given name. It reports
 433 // whether there were any failures.
 434 //
 435 // A subbenchmark is like any other benchmark. A benchmark that calls Run at
 436 // least once will not be measured itself.
 437 func (b *B) runBench(name string, f func(b *B)) bool {
 438         // Since b has subbenchmarks, we will no longer run it as a benchmark itself.
 439         // Release the lock and acquire it on exit to ensure locks stay paired.
 440         b.hasSub = true
 441         benchmarkLock.Unlock()
 442         defer benchmarkLock.Lock()
 443
 444         benchName, ok := b.name, true
 445         if b.context != nil {
 446                 benchName, ok = b.context.match.fullName(&b.common, name)
 447         }
 448         if !ok {
 449                 return true
 450         }
 451         sub := &B{
 452                 common: common{
 453                         signal: make(chan bool),
 454                         name:   benchName,
 455                         parent: &b.common,
 456                         level:  b.level + 1,
 457                 },
 458                 benchFunc: f,
 459                 benchTime: b.benchTime,
 460                 context:   b.context,
 461         }
 462         if sub.probe(); !sub.hasSub {
 463                 b.add(sub.run())
 464         }
 465         return !sub.failed
 466 }
 467
 468 // add simulates running benchmarks in sequence in a single iteration. It is
 469 // used to give some meaningful results in case func Benchmark is used in
 470 // combination with Run.
 471 func (b *B) add(other BenchmarkResult) {
 472         r := &b.result
 473         // The aggregated BenchmarkResults resemble running all subbenchmarks as
 474         // in sequence in a single benchmark.
 475         r.N = 1
 476         r.T += time.Duration(other.NsPerOp())
 477         if other.Bytes == 0 {
 478                 // Summing Bytes is meaningless in aggregate if not all subbenchmarks
 479                 // set it.
 480                 b.missingBytes = true
 481                 r.Bytes = 0
 482         }
 483         if !b.missingBytes {
 484                 r.Bytes += other.Bytes
 485         }
 486         r.MemAllocs += uint64(other.AllocsPerOp())
 487         r.MemBytes += uint64(other.AllocedBytesPerOp())
 488 }
 489
 490 // trimOutput shortens the output from a benchmark, which can be very long.
 491 func (b *B) trimOutput() {
 492         // The output is likely to appear multiple times because the benchmark
 493         // is run multiple times, but at least it will be seen. This is not a big deal
 494         // because benchmarks rarely print, but just in case, we trim it if it's too long.
 495         const maxNewlines = 10
 496         for nlCount, j := 0, 0; j < len(b.output); j++ {
 497                 if b.output[j] == '\n' {
 498                         nlCount++
 499                         if nlCount >= maxNewlines {
 500                                 b.output = append(b.output[:j], "\n\t... [output truncated]\n"...)
 501                                 break
 502                         }
 503                 }
 504         }
 505 }
 506
 507 // A PB is used by RunParallel for running parallel benchmarks.
 508 type PB struct {
 509         globalN *uint64 // shared between all worker goroutines iteration counter
 510         grain   uint64  // acquire that many iterations from globalN at once
 511         cache   uint64  // local cache of acquired iterations
 512         bN      uint64  // total number of iterations to execute (b.N)
 513 }
 514
 515 // Next reports whether there are more iterations to execute.
 516 func (pb *PB) Next() bool {
 517         if pb.cache == 0 {
 518                 n := atomic.AddUint64(pb.globalN, pb.grain)
 519                 if n <= pb.bN {
 520                         pb.cache = pb.grain
 521                 } else if n < pb.bN+pb.grain {
 522                         pb.cache = pb.bN + pb.grain - n
 523                 } else {
 524                         return false
 525                 }
 526         }
 527         pb.cache--
 528         return true
 529 }
 530
 531 // RunParallel runs a benchmark in parallel.
 532 // It creates multiple goroutines and distributes b.N iterations among them.
 533 // The number of goroutines defaults to GOMAXPROCS. To increase parallelism for
 534 // non-CPU-bound benchmarks, call SetParallelism before RunParallel.
 535 // RunParallel is usually used with the go test -cpu flag.
 536 //
 537 // The body function will be run in each goroutine. It should set up any
 538 // goroutine-local state and then iterate until pb.Next returns false.
 539 // It should not use the StartTimer, StopTimer, or ResetTimer functions,
 540 // because they have global effect. It should also not call Run.
 541 func (b *B) RunParallel(body func(*PB)) {
 542         if b.N == 0 {
 543                 return // Nothing to do when probing.
 544         }
 545         // Calculate grain size as number of iterations that take ~100µs.
 546         // 100µs is enough to amortize the overhead and provide sufficient
 547         // dynamic load balancing.
 548         grain := uint64(0)
 549         if b.previousN > 0 && b.previousDuration > 0 {
 550                 grain = 1e5 * uint64(b.previousN) / uint64(b.previousDuration)
 551         }
 552         if grain < 1 {
 553                 grain = 1
 554         }
 555         // We expect the inner loop and function call to take at least 10ns,
 556         // so do not do more than 100µs/10ns=1e4 iterations.
 557         if grain > 1e4 {
 558                 grain = 1e4
 559         }
 560
 561         n := uint64(0)
 562         numProcs := b.parallelism * runtime.GOMAXPROCS(0)
 563         var wg sync.WaitGroup
 564         wg.Add(numProcs)
 565         for p := 0; p < numProcs; p++ {
 566                 go func() {
 567                         defer wg.Done()
 568                         pb := &PB{
 569                                 globalN: &n,
 570                                 grain:   grain,
 571                                 bN:      uint64(b.N),
 572                         }
 573                         body(pb)
 574                 }()
 575         }
 576         wg.Wait()
 577         if n <= uint64(b.N) && !b.Failed() {
 578                 b.Fatal("RunParallel: body exited without pb.Next() == false")
 579         }
 580 }
 581
 582 // SetParallelism sets the number of goroutines used by RunParallel to p*GOMAXPROCS.
 583 // There is usually no need to call SetParallelism for CPU-bound benchmarks.
 584 // If p is less than 1, this call will have no effect.
 585 func (b *B) SetParallelism(p int) {
 586         if p >= 1 {
 587                 b.parallelism = p
 588         }
 589 }
 590
 591 // Benchmark benchmarks a single function. Useful for creating
 592 // custom benchmarks that do not use the "go test" command.
 593 func Benchmark(f func(b *B)) BenchmarkResult {
 594         b := &B{
 595                 common: common{
 596                         signal: make(chan bool),
 597                 },
 598                 benchFunc: f,
 599                 benchTime: *benchTime,
 600         }
 601         return b.run()
 602 }