Add metrics to simulator

cmd/simulator/load/funder.go

@@ -21,7 +21,7 @@ import (
 // DistributeFunds ensures that each address in keys has at least [minFundsPerAddr] by sending funds
 // from the key with the highest starting balance.
 // This function returns a set of at least [numKeys] keys, each having a minimum balance [minFundsPerAddr].
-func DistributeFunds(ctx context.Context, client ethclient.Client, keys []*key.Key, numKeys int, minFundsPerAddr *big.Int) ([]*key.Key, error) {
+func DistributeFunds(ctx context.Context, client ethclient.Client, keys []*key.Key, numKeys int, minFundsPerAddr *big.Int, blockchainID string) ([]*key.Key, error) {
 	if len(keys) < numKeys {
 		return nil, fmt.Errorf("insufficient number of keys %d < %d", len(keys), numKeys)
 	}
@@ -107,6 +107,7 @@ func DistributeFunds(ctx context.Context, client ethclient.Client, keys []*key.K
 		return nil, fmt.Errorf("failed to generate fund distribution sequence from %s of length %d", maxFundsKey.Address, len(needFundsAddrs))
 	}
 	worker := NewSingleAddressTxWorker(ctx, client, maxFundsKey.Address)
+
 	txFunderAgent := txs.NewIssueNAgent[*types.Transaction](txSequence, worker, numTxs)
 
 	if err := txFunderAgent.Execute(ctx); err != nil {

cmd/simulator/load/loader.go

@@ -7,7 +7,11 @@ import (
 	"context"
 	"crypto/ecdsa"
 	"fmt"
+	"io/ioutil"
 	"math/big"
+	"net/http"
+	"regexp"
+	"time"
 
 	"github.com/ava-labs/subnet-evm/cmd/simulator/config"
 	"github.com/ava-labs/subnet-evm/cmd/simulator/key"
@@ -31,6 +35,14 @@ func ExecuteLoader(ctx context.Context, config config.Config) error {
 
 	// Construct the arguments for the load simulator
 	clients := make([]ethclient.Client, 0, len(config.Endpoints))
+	// Extract blockchainStrID from the clientURI
+	re := regexp.MustCompile(`bc\/(.*)\/ws`)
+	matches := re.FindStringSubmatch(config.Endpoints[0])
+	if len(matches) < 1 {
+		return fmt.Errorf("failed to get blockchainStrID from the clientURI %s", config.Endpoints[0])
+	}
+	// Get the last element in matches
+	blockchainIDStr := matches[len(matches)-1]
 	for i := 0; i < config.Workers; i++ {
 		clientURI := config.Endpoints[i%len(config.Endpoints)]
 		client, err := ethclient.Dial(clientURI)
@@ -63,7 +75,7 @@ func ExecuteLoader(ctx context.Context, config config.Config) error {
 	maxFeeCap := new(big.Int).Mul(big.NewInt(params.GWei), big.NewInt(config.MaxFeeCap))
 	minFundsPerAddr := new(big.Int).Mul(maxFeeCap, big.NewInt(int64(config.TxsPerWorker*params.TxGas)))
 	log.Info("Distributing funds", "numTxsPerWorker", config.TxsPerWorker, "minFunds", minFundsPerAddr)
-	keys, err = DistributeFunds(ctx, clients[0], keys, config.Workers, minFundsPerAddr)
+	keys, err = DistributeFunds(ctx, clients[0], keys, config.Workers, minFundsPerAddr, blockchainIDStr)
 	if err != nil {
 		return err
 	}
@@ -129,5 +141,39 @@ func ExecuteLoader(ctx context.Context, config config.Config) error {
 		return err
 	}
 	log.Info("Tx agents completed successfully.")
+
+	logOtherMetrics(blockchainIDStr)
+	return nil
+}
+
+func logOtherMetrics(blockchainIDStr string) error {
+	getCallStart := time.Now()
+	resp, err := http.Get("http://127.0.0.1:9650/ext/metrics")
+	getCallEnd := time.Now()
+	getCallDuration := getCallEnd.Sub(getCallStart)
+
+	log.Info("GET Metrics API Data", "time", getCallDuration.Seconds())
+	if err != nil {
+		return fmt.Errorf("failed getting metrics: %w", err)
+	}
+
+	body, err := ioutil.ReadAll(resp.Body)
+	if err != nil {
+		return fmt.Errorf("failed reading response body of metrics: %w", err)
+	}
+
+	bodyString := string(body)
+	re := regexp.MustCompile(fmt.Sprintf(".*avalanche_%s_vm_metervm_build_block_sum.*", blockchainIDStr))
+	matches := re.FindAllStringSubmatch(bodyString, -1)
+	log.Info("Sum of time (in ns) of a build_block", "time", matches[len(matches)-1])
+
+	re = regexp.MustCompile(fmt.Sprintf(".*avalanche_%s_blks_accepted_sum.*", blockchainIDStr))
+	matches = re.FindAllStringSubmatch(bodyString, -1)
+	log.Info("Sum of time (in ns) from issuance of a block(s) to its acceptance", "time", matches[len(matches)-1])
+
+	re = regexp.MustCompile(fmt.Sprintf(".*avalanche_%s_vm_metervm_verify_sum.*", blockchainIDStr))
+	matches = re.FindAllStringSubmatch(bodyString, -1)
+	log.Info("Sum of time (in ns) of a verify", "time", matches[len(matches)-1])
+
 	return nil
 }

cmd/simulator/txs/agent.go

@@ -7,6 +7,9 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"time"
+
+	"github.com/ethereum/go-ethereum/log"
 )
 
 // TxSequence provides an interface to return a channel of transactions.
@@ -53,33 +56,70 @@ func (a issueNAgent[T]) Execute(ctx context.Context) error {
 	}
 
 	txChan := a.sequence.Chan()
+	confirmedCount := 0
+	batchI := 1
+
+	// Tracks the total amount of time waiting for issuing and confirming txs
+	var (
+		totalIssuedTime    time.Duration
+		totalConfirmedTime time.Duration
+	)
+
+	defer func() error {
+		return a.worker.Close(ctx)
+	}()
 
+	// Start time for execution
+	start := time.Now()
 	for {
 		var (
-			txs = make([]T, 0, a.n)
-			tx  T
-			ok  bool
+			txs     = make([]T, 0, a.n)
+			tx      T
+			moreTxs bool
 		)
+		// Start issuance batch
+		issuedStart := time.Now()
+	L:
 		for i := uint64(0); i < a.n; i++ {
 			select {
-			case tx, ok = <-txChan:
-				if !ok {
-					return a.worker.Close(ctx)
-				}
 			case <-ctx.Done():
 				return ctx.Err()
+			case tx, moreTxs = <-txChan:
+				if !moreTxs {
+					break L
+				}
+				if err := a.worker.IssueTx(ctx, tx); err != nil {
+					return fmt.Errorf("failed to issue transaction %d: %w", len(txs), err)
+				}
+				txs = append(txs, tx)
 			}
-
-			if err := a.worker.IssueTx(ctx, tx); err != nil {
-				return fmt.Errorf("failed to issue transaction %d: %w", len(txs), err)
-			}
-			txs = append(txs, tx)
 		}
+		// Get the batch's issuance time and add it to totalIssuedTime
+		issuedDuration := time.Since(issuedStart)
+		log.Info("Issuance Batch Done", "batch", batchI, "time", issuedDuration.Seconds())
+		totalIssuedTime += issuedDuration
 
+		// Wait for txs in this batch to confirm
+		confirmedStart := time.Now()
 		for i, tx := range txs {
 			if err := a.worker.ConfirmTx(ctx, tx); err != nil {
 				return fmt.Errorf("failed to await transaction %d: %w", i, err)
 			}
+			confirmedCount++
 		}
+		// Get the batch's confirmation time and add it to totalConfirmedTime
+		confirmedDuration := time.Since(confirmedStart)
+		log.Info("Confirmed Batch Done", "batch", batchI, "time", confirmedDuration.Seconds())
+		totalConfirmedTime += confirmedDuration
+
+		// Check if this is the last batch, if so write the final log and return
+		if !moreTxs {
+			totalTime := time.Since(start).Seconds()
+			log.Info("Execution complete", "totalTxs", confirmedCount, "totalTime", totalTime, "TPS", float64(confirmedCount)/totalTime,
+				"issuanceTime", totalIssuedTime.Seconds(), "confirmedTime", totalConfirmedTime.Seconds())
+			return nil
+		}
+
+		batchI++
 	}
 }

ethclient/ethclient.go

@@ -384,7 +384,7 @@ func (ec *client) SubscribeNewAcceptedTransactions(ctx context.Context, ch chan<
 	return ec.c.EthSubscribe(ctx, ch, "newAcceptedTransactions")
 }
 
-// SubscribeNewAcceptedTransactions subscribes to notifications about the accepted transaction hashes on the given channel.
+// SubscribeNewPendingTransactions subscribes to notifications about the pending transaction hashes on the given channel.
 func (ec *client) SubscribeNewPendingTransactions(ctx context.Context, ch chan<- *common.Hash) (interfaces.Subscription, error) {
 	return ec.c.EthSubscribe(ctx, ch, "newPendingTransactions")
 }