Merge pull request #141 from coinbase/patrick/log-blocks-per-second

Log Blocks Synced Per Second

Author: patrick-ogrady

pkg/logger/logger.go

@@ -34,6 +34,9 @@ import (
 var _ statefulsyncer.Logger = (*Logger)(nil)
 
 const (
+	// TimeElapsedCounter tracks the total time elapsed in seconds.
+	TimeElapsedCounter = "time_elapsed"
+
 	// blockStreamFile contains the stream of processed
 	// blocks and whether they were added or removed.
 	blockStreamFile = "blocks.txt"
@@ -107,6 +110,17 @@ func (l *Logger) LogDataStats(ctx context.Context) error {
 		return nil
 	}
 
+	elapsedTime, err := l.CounterStorage.Get(ctx, TimeElapsedCounter)
+	if err != nil {
+		return fmt.Errorf("%w cannot get elapsed time", err)
+	}
+
+	if elapsedTime.Sign() == 0 { // wait for at least some elapsed time
+		return nil
+	}
+
+	blocksPerSecond := new(big.Int).Div(blocks, elapsedTime)
+
 	orphans, err := l.CounterStorage.Get(ctx, storage.OrphanCounter)
 	if err != nil {
 		return fmt.Errorf("%w cannot get orphan counter", err)
@@ -133,9 +147,10 @@ func (l *Logger) LogDataStats(ctx context.Context) error {
 	}
 
 	statsMessage := fmt.Sprintf(
-		"[STATS] Blocks: %s (Orphaned: %s) Transactions: %s Operations: %s",
+		"[STATS] Blocks: %s (Orphaned: %s, Rate: %s/sec) Transactions: %s Operations: %s",
 		blocks.String(),
 		orphans.String(),
+		blocksPerSecond.String(),
 		txs.String(),
 		ops.String(),
 	)

pkg/tester/data.go

@@ -19,6 +19,7 @@ import (
 	"errors"
 	"fmt"
 	"log"
+	"math/big"
 	"os"
 	"time"
 
@@ -49,16 +50,15 @@ const (
 	// until the client halts the search or the block is found).
 	InactiveFailureLookbackWindow = 250
 
+	// periodicLoggingSeconds is the frequency to print stats in seconds.
+	periodicLoggingSeconds = 10
+
 	// PeriodicLoggingFrequency is the frequency that stats are printed
 	// to the terminal.
-	//
-	// TODO: make configurable
-	PeriodicLoggingFrequency = 10 * time.Second
+	PeriodicLoggingFrequency = periodicLoggingSeconds * time.Second
 
 	// EndAtTipCheckInterval is the frequency that EndAtTip condition
 	// is evaludated
-	//
-	// TODO: make configurable
 	EndAtTipCheckInterval = 10 * time.Second
 )
 
@@ -357,6 +357,13 @@ func (t *DataTester) StartPeriodicLogger(
 
 			return ctx.Err()
 		case <-tc.C:
+			// Update the elapsed time in counter storage so that
+			// we can log metrics about the current check:data run.
+			_, _ = t.counterStorage.Update(
+				ctx,
+				logger.TimeElapsedCounter,
+				big.NewInt(periodicLoggingSeconds),
+			)
 			_ = t.logger.LogDataStats(ctx)
 		}
 	}