internal/fuzz: log average execs/sec since last log

This change also fixes a bug with calculating the
total interesting count. When fuzzing with an empty
corpus, the fuzzing engine adds an starting corpus
value in that run in order to start fuzzing. That
meant that the interesting total count was off by one:
it would start at 1, even though the cache was empty.
Added some tests for this as well.

Fixes #48787

Change-Id: I47acf96f0a0797214ebb24a95366d8460bf303bc
Reviewed-on: https://go-review.googlesource.com/c/go/+/354150
Trust: Katie Hockman <katie@golang.org>
Run-TryBot: Katie Hockman <katie@golang.org>
TryBot-Result: Go Bot <gobot@golang.org>
Reviewed-by: Jay Conrod <jayconrod@google.com>
Reviewed-by: Roland Shoemaker <roland@golang.org>

1 files changed, 19 insertions, 8 deletions

diff --git a/src/internal/fuzz/fuzz.go b/src/internal/fuzz/fuzz.go
index 87f5459afd..2c2a365f4c 100644
--- a/src/internal/fuzz/fuzz.go
+++ b/src/internal/fuzz/fuzz.go
@@ -556,6 +556,13 @@ type coordinator struct {
 	// count is the number of values fuzzed so far.
 	count int64
 
+	// countLastLog is the number of values fuzzed when the output was last
+	// logged.
+	countLastLog int64
+
+	// timeLastLog is the time at which the output was last logged.
+	timeLastLog time.Time
+
 	// interestingCount is the number of unique interesting values which have
 	// been found this execution.
 	interestingCount int64
@@ -618,12 +625,13 @@ func newCoordinator(opts CoordinateFuzzingOpts) (*coordinator, error) {
 		return nil, err
 	}
 	c := &coordinator{
-		opts:      opts,
-		startTime: time.Now(),
-		inputC:    make(chan fuzzInput),
-		minimizeC: make(chan fuzzMinimizeInput),
-		resultC:   make(chan fuzzResult),
-		corpus:    corpus,
+		opts:        opts,
+		startTime:   time.Now(),
+		inputC:      make(chan fuzzInput),
+		minimizeC:   make(chan fuzzMinimizeInput),
+		resultC:     make(chan fuzzResult),
+		corpus:      corpus,
+		timeLastLog: time.Now(),
 	}
 	if opts.MinimizeLimit > 0 || opts.MinimizeTimeout > 0 {
 		for _, t := range opts.Types {
@@ -676,6 +684,7 @@ func (c *coordinator) updateStats(result fuzzResult) {
 }
 
 func (c *coordinator) logStats() {
+	now := time.Now()
 	if c.warmupRun() {
 		runSoFar := c.warmupInputCount - c.warmupInputLeft
 		if coverageEnabled {
@@ -684,14 +693,16 @@ func (c *coordinator) logStats() {
 			fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, testing seed corpus: %d/%d completed\n", c.elapsed(), runSoFar, c.warmupInputCount)
 		}
 	} else {
-		rate := float64(c.count) / time.Since(c.startTime).Seconds() // be more precise here
+		rate := float64(c.count-c.countLastLog) / now.Sub(c.timeLastLog).Seconds()
 		if coverageEnabled {
-			interestingTotalCount := len(c.corpus.entries) - len(c.opts.Seed)
+			interestingTotalCount := int64(c.warmupInputCount-len(c.opts.Seed)) + c.interestingCount
 			fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, execs: %d (%.0f/sec), new interesting: %d (total: %d)\n", c.elapsed(), c.count, rate, c.interestingCount, interestingTotalCount)
 		} else {
 			fmt.Fprintf(c.opts.Log, "fuzz: elapsed: %s, execs: %d (%.0f/sec)", c.elapsed(), c.count, rate)
 		}
 	}
+	c.countLastLog = c.count
+	c.timeLastLog = now
 }
 
 // peekInput returns the next value that should be sent to workers.