Loadbot duration metrics (#301)

* Gracefully handle shutdown errors

* Add support for duration tracking

* Add more complex wait times

* Use a syncMap for tracking txn execution times

* Remove leftover file

* Add block metrics to the loadbot

* Resolve minor code fragments

command/loadbot/execution.go

@@ -16,6 +16,14 @@ import (
 	"github.com/umbracle/go-web3/jsonrpc"
 )
 
+const (
+	maxReceiptWait = 5 * time.Minute
+	minReceiptWait = 30 * time.Second
+
+	defaultFastestTurnAround = time.Hour * 24
+	defaultSlowestTurnAround = time.Duration(0)
+)
+
 type Account struct {
 	Address    types.Address
 	PrivateKey *ecdsa.PrivateKey
@@ -30,19 +38,126 @@ type Configuration struct {
 	MaxConns int
 }
 
+type metadata struct {
+	// turn around time for the transaction
+	turnAroundTime time.Duration
+
+	// block where it was sealed
+	blockNumber uint64
+}
+
+type ExecDuration struct {
+	// turnAroundMap maps the transaction hash -> turn around time for passing transactions
+	turnAroundMap     sync.Map
+	turnAroundMapSize uint64
+
+	// blockTransactions maps how many transactions went into a block
+	blockTransactions map[uint64]uint64
+
+	// Arrival Time - Time at which the transaction is added
+	// Completion Time -Time at which the transaction is sealed
+	// Turn around time - Completion Time – Arrival Time
+
+	// AverageTurnAround is the average turn around time for all passing transactions
+	AverageTurnAround time.Duration
+
+	// FastestTurnAround is the fastest turn around time recorded for a transaction
+	FastestTurnAround time.Duration
+
+	// SlowestTurnAround is the slowest turn around time recorded for a transaction
+	SlowestTurnAround time.Duration
+
+	// TotalExecTime is the total execution time for a single loadbot run
+	TotalExecTime time.Duration
+}
+
+// calcTurnAroundMetrics updates the turn around metrics based on the turnAroundMap
+func (ed *ExecDuration) calcTurnAroundMetrics() {
+	// Set the initial values
+	fastestTurnAround := defaultFastestTurnAround
+	slowestTurnAround := defaultSlowestTurnAround
+	totalPassing := atomic.LoadUint64(&ed.turnAroundMapSize)
+	var zeroTime time.Time  // Zero time
+	var totalTime time.Time // Zero time used for tracking
+
+	if totalPassing == 0 {
+		// No data to show, use zero data
+		zeroDuration := time.Duration(0)
+		ed.SlowestTurnAround = zeroDuration
+		ed.FastestTurnAround = zeroDuration
+		ed.AverageTurnAround = zeroDuration
+
+		return
+	}
+
+	ed.turnAroundMap.Range(func(_, value interface{}) bool {
+		data := value.(*metadata)
+		turnAroundTime := data.turnAroundTime
+
+		// Update the duration metrics
+		if turnAroundTime < fastestTurnAround {
+			fastestTurnAround = turnAroundTime
+		}
+
+		if turnAroundTime > slowestTurnAround {
+			slowestTurnAround = turnAroundTime
+		}
+
+		totalTime = totalTime.Add(turnAroundTime)
+
+		ed.blockTransactions[data.blockNumber]++
+
+		return true
+	})
+
+	averageDuration := (totalTime.Sub(zeroTime)) / time.Duration(totalPassing)
+
+	ed.SlowestTurnAround = slowestTurnAround
+	ed.FastestTurnAround = fastestTurnAround
+	ed.AverageTurnAround = averageDuration
+}
+
+// reportExecTime reports the turn around time for a transaction
+// for a single loadbot run
+func (ed *ExecDuration) reportTurnAroundTime(
+	txHash web3.Hash,
+	data *metadata,
+) {
+	ed.turnAroundMap.Store(txHash, data)
+	atomic.AddUint64(&ed.turnAroundMapSize, 1)
+}
+
 type Metrics struct {
 	TotalTransactionsSentCount uint64
 	FailedTransactionsCount    uint64
+	TransactionDuration        ExecDuration
 }
 
 type Loadbot struct {
 	cfg     *Configuration
 	metrics *Metrics
 }
 
+// calcMaxTimeout calculates the max timeout for transactions receipts
+// based on the transaction count and tps params
+func calcMaxTimeout(count, tps uint64) time.Duration {
+	waitTime := minReceiptWait
+	// The receipt timeout should be at max maxReceiptWait
+	// or minReceiptWait + tps / count * 100
+	// This way the wait time scales linearly for more stressful situations
+	waitFactor := time.Duration(float64(tps)/float64(count)*100) * time.Second
+
+	if waitTime+waitFactor > maxReceiptWait {
+		return maxReceiptWait
+	}
+
+	return waitTime + waitFactor
+}
+
 func NewLoadBot(cfg *Configuration, metrics *Metrics) *Loadbot {
 	return &Loadbot{cfg: cfg, metrics: metrics}
 }
+
 func getInitialSenderNonce(client *jsonrpc.Client, address types.Address) (uint64, error) {
 	nonce, err := client.Eth().GetNonce(web3.Address(address), web3.Latest)
 	if err != nil {
@@ -85,7 +200,10 @@ func (l *Loadbot) Run() error {
 	if err != nil {
 		return fmt.Errorf("an error has occured while creating JSON-RPC client: %v", err)
 	}
-	defer shutdownClient(client)
+
+	defer func(client *jsonrpc.Client) {
+		_ = shutdownClient(client)
+	}(client)
 
 	nonce, err := getInitialSenderNonce(client, sender.Address)
 	if err != nil {
@@ -97,6 +215,9 @@ func (l *Loadbot) Run() error {
 
 	var wg sync.WaitGroup
 
+	receiptTimeout := calcMaxTimeout(l.cfg.Count, l.cfg.TPS)
+
+	startTime := time.Now()
 	for i := uint64(0); i < l.cfg.Count; i++ {
 		<-ticker.C
 
@@ -108,23 +229,44 @@ func (l *Loadbot) Run() error {
 
 			// take nonce first
 			newNextNonce := atomic.AddUint64(&nonce, 1)
+
+			// Start the performance timer
+			start := time.Now()
+
+			// Execute the transaction
 			txHash, err := executeTxn(client, *sender, l.cfg.Receiver, l.cfg.Value, newNextNonce-1)
 			if err != nil {
 				atomic.AddUint64(&l.metrics.FailedTransactionsCount, 1)
 				return
 			}
 
-			ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+			ctx, cancel := context.WithTimeout(context.Background(), receiptTimeout)
 			defer cancel()
 
-			_, err = tests.WaitForReceipt(ctx, client.Eth(), txHash)
+			receipt, err := tests.WaitForReceipt(ctx, client.Eth(), txHash)
 			if err != nil {
 				atomic.AddUint64(&l.metrics.FailedTransactionsCount, 1)
 				return
 			}
+
+			// Stop the performance timer
+			end := time.Now()
+			l.metrics.TransactionDuration.reportTurnAroundTime(
+				txHash,
+				&metadata{
+					turnAroundTime: end.Sub(start),
+					blockNumber:    receipt.BlockNumber,
+				},
+			)
 		}()
 	}
 
 	wg.Wait()
+	endTime := time.Now()
+
+	// Calculate the turn around metrics now that the loadbot is done
+	l.metrics.TransactionDuration.calcTurnAroundMetrics()
+	l.metrics.TransactionDuration.TotalExecTime = endTime.Sub(startTime)
+
 	return nil
 }

command/loadbot/loadbot_command.go

@@ -3,17 +3,22 @@ package loadbot
 import (
 	"bytes"
 	"fmt"
-	"net/url"
-
 	"github.com/0xPolygon/polygon-sdk/command/helper"
+	"github.com/0xPolygon/polygon-sdk/helper/common"
 	"github.com/0xPolygon/polygon-sdk/types"
+	"net/url"
+	"sort"
 )
 
 type LoadbotCommand struct {
 	helper.Base
 	Formatter *helper.FormatterFlag
 }
 
+const (
+	durationPrecision = 5
+)
+
 func (l *LoadbotCommand) DefineFlags() {
 	l.Base.DefineFlags(l.Formatter)
 
@@ -153,6 +158,9 @@ func (l *LoadbotCommand) Run(args []string) int {
 	metrics := &Metrics{
 		TotalTransactionsSentCount: 0,
 		FailedTransactionsCount:    0,
+		TransactionDuration: ExecDuration{
+			blockTransactions: make(map[uint64]uint64),
+		},
 	}
 
 	// create a loadbot instance
@@ -165,27 +173,115 @@ func (l *LoadbotCommand) Run(args []string) int {
 	}
 
 	res := &LoadbotResult{
-		Total:  metrics.TotalTransactionsSentCount,
-		Failed: metrics.FailedTransactionsCount,
+		CountData: TxnCountData{
+			Total:  metrics.TotalTransactionsSentCount,
+			Failed: metrics.FailedTransactionsCount,
+		},
 	}
+	res.extractExecutionData(metrics)
+
 	l.Formatter.OutputResult(res)
 
 	return 0
 }
 
-type LoadbotResult struct {
+type TxnCountData struct {
 	Total  uint64 `json:"total"`
 	Failed uint64 `json:"failed"`
 }
 
-func (r *LoadbotResult) Output() string {
+type TxnTurnAroundData struct {
+	FastestTurnAround float64 `json:"fastestTurnAround"`
+	SlowestTurnAround float64 `json:"slowestTurnAround"`
+	AverageTurnAround float64 `json:"averageTurnAround"`
+	TotalExecTime     float64 `json:"totalExecTime"`
+}
+
+type TxnBlockData struct {
+	// BlocksRequired is the required number of blocks to seal the data
+	BlocksRequired uint64 `json:"blocksRequired"`
+
+	// BlockTransactionsMap maps the block number to the number of loadbot transactions in it
+	BlockTransactionsMap map[uint64]uint64 `json:"blockTransactionsMap"`
+}
+
+type LoadbotResult struct {
+	CountData      TxnCountData      `json:"countData"`
+	TurnAroundData TxnTurnAroundData `json:"turnAroundData"`
+	BlockData      TxnBlockData      `json:"blockData"`
+}
+
+func (lr *LoadbotResult) extractExecutionData(metrics *Metrics) {
+	lr.TurnAroundData.FastestTurnAround = common.ToFixedFloat(
+		metrics.TransactionDuration.FastestTurnAround.Seconds(),
+		durationPrecision,
+	)
+
+	lr.TurnAroundData.SlowestTurnAround = common.ToFixedFloat(
+		metrics.TransactionDuration.SlowestTurnAround.Seconds(),
+		durationPrecision,
+	)
+
+	lr.TurnAroundData.AverageTurnAround = common.ToFixedFloat(
+		metrics.TransactionDuration.AverageTurnAround.Seconds(),
+		durationPrecision,
+	)
+
+	lr.TurnAroundData.TotalExecTime = common.ToFixedFloat(
+		metrics.TransactionDuration.TotalExecTime.Seconds(),
+		durationPrecision,
+	)
+
+	lr.BlockData = TxnBlockData{
+		BlocksRequired:       uint64(len(metrics.TransactionDuration.blockTransactions)),
+		BlockTransactionsMap: metrics.TransactionDuration.blockTransactions,
+	}
+}
+
+func (lr *LoadbotResult) Output() string {
 	var buffer bytes.Buffer
 
-	buffer.WriteString("\n[LOADBOT RUN]\n")
+	buffer.WriteString("\n=====[LOADBOT RUN]=====\n")
+	buffer.WriteString("\n[COUNT DATA]\n")
+	buffer.WriteString(helper.FormatKV([]string{
+		fmt.Sprintf("Transactions submitted|%d", lr.CountData.Total),
+		fmt.Sprintf("Transactions failed|%d", lr.CountData.Failed),
+	}))
+
+	buffer.WriteString("\n\n[TURN AROUND DATA]\n")
 	buffer.WriteString(helper.FormatKV([]string{
-		fmt.Sprintf("Transactions submitted|%d", r.Total),
-		fmt.Sprintf("Transactions failed|%d", r.Failed),
+		fmt.Sprintf("Average transaction turn around|%fs", lr.TurnAroundData.AverageTurnAround),
+		fmt.Sprintf("Fastest transaction turn around|%fs", lr.TurnAroundData.FastestTurnAround),
+		fmt.Sprintf("Slowest transaction turn around|%fs", lr.TurnAroundData.SlowestTurnAround),
+		fmt.Sprintf("Total loadbot execution time|%fs", lr.TurnAroundData.TotalExecTime),
 	}))
+
+	buffer.WriteString("\n\n[BLOCK DATA]\n")
+	buffer.WriteString(helper.FormatKV([]string{
+		fmt.Sprintf("Blocks required|%d", lr.BlockData.BlocksRequired),
+	}))
+
+	if lr.BlockData.BlocksRequired != 0 {
+		buffer.WriteString("\n\n")
+
+		keys := make([]uint64, 0, lr.BlockData.BlocksRequired)
+		for k := range lr.BlockData.BlockTransactionsMap {
+			keys = append(keys, k)
+		}
+		sort.Slice(keys, func(i, j int) bool {
+			return keys[i] < keys[j]
+		})
+
+		formattedStrings := make([]string, 0)
+		for _, blockNumber := range keys {
+			formattedStrings = append(formattedStrings,
+				fmt.Sprintf("Block #%d|%d txns", blockNumber, lr.BlockData.BlockTransactionsMap[blockNumber]),
+			)
+		}
+
+		buffer.WriteString(helper.FormatKV(formattedStrings))
+	}
+
 	buffer.WriteString("\n")
 
 	return buffer.String()

helper/common/common.go

@@ -2,6 +2,7 @@ package common
 
 import (
 	"fmt"
+	"math"
 	"os"
 	"path/filepath"
 )
@@ -24,6 +25,15 @@ func Max(a, b uint64) uint64 {
 	return b
 }
 
+func roundFloat(num float64) int {
+	return int(num + math.Copysign(0.5, num))
+}
+
+func ToFixedFloat(num float64, precision int) float64 {
+	output := math.Pow(10, float64(precision))
+	return float64(roundFloat(num*output)) / output
+}
+
 // SetupDataDir sets up the data directory and the corresponding sub-directories
 func SetupDataDir(dataDir string, paths []string) error {
 	if err := createDir(dataDir); err != nil {