Update wallet to report tx processing duration via event handlers

tests/fixture/e2e/helpers.go

@@ -19,7 +19,6 @@ import (
 	"go.uber.org/zap"
 
 	"github.com/ava-labs/avalanchego/config"
-	"github.com/ava-labs/avalanchego/ids"
 	"github.com/ava-labs/avalanchego/tests"
 	"github.com/ava-labs/avalanchego/tests/fixture/tmpnet"
 	"github.com/ava-labs/avalanchego/utils/crypto/secp256k1"
@@ -76,13 +75,9 @@ func NewWallet(tc tests.TestContext, keychain *secp256k1fx.Keychain, nodeURI tmp
 	require.NoError(tc, err)
 	wallet := primary.NewWalletWithOptions(
 		baseWallet,
-		common.WithPostIssuanceFunc(
-			func(id ids.ID) {
-				tc.Log().Info("issued transaction",
-					zap.Stringer("txID", id),
-				)
-			},
-		),
+		common.WithLoggedIssuranceAndConfirmation(tc.Log()),
+		// Use a low poll frequency to ensure more accurate determination of confirmation duration
+		common.WithPollFrequency(10*time.Millisecond),
 	)
 	OutputWalletBalances(tc, wallet)
 	return wallet

vms/platformvm/txs/txstest/wallet.go

@@ -7,6 +7,7 @@ import (
 	"context"
 	"math"
 	"testing"
+	"time"
 
 	"github.com/stretchr/testify/require"
 
@@ -126,9 +127,9 @@ func (c *client) IssueTx(
 	options ...common.Option,
 ) error {
 	ops := common.NewOptions(options)
-	if f := ops.PostIssuanceFunc(); f != nil {
+	if f := ops.PostIssuanceHandler(); f != nil {
 		txID := tx.ID()
-		f(txID)
+		f(common.PChainAlias, txID, time.Duration(0))
 	}
 	ctx := ops.Context()
 	return c.backend.AcceptTx(ctx, tx)

wallet/chain/c/wallet.go

@@ -149,13 +149,15 @@ func (w *wallet) IssueAtomicTx(
 ) error {
 	ops := common.NewOptions(options)
 	ctx := ops.Context()
+	startTime := time.Now()
 	txID, err := w.avaxClient.IssueTx(ctx, tx.SignedBytes())
+	issuanceDuration := time.Since(startTime)
 	if err != nil {
 		return err
 	}
 
-	if f := ops.PostIssuanceFunc(); f != nil {
-		f(txID)
+	if f := ops.PostIssuanceHandler(); f != nil {
+		f(common.PChainAlias, txID, issuanceDuration)
 	}
 
 	if ops.AssumeDecided() {
@@ -165,6 +167,12 @@ func (w *wallet) IssueAtomicTx(
 	if err := awaitTxAccepted(w.avaxClient, ctx, txID, ops.PollFrequency()); err != nil {
 		return err
 	}
+	totalDuration := time.Since(startTime)
+	issuanceToConfirmationDuration := totalDuration - issuanceDuration
+
+	if f := ops.PostConfirmationHandler(); f != nil {
+		f(common.CChainAlias, txID, totalDuration, issuanceToConfirmationDuration)
+	}
 
 	return w.Backend.AcceptAtomicTx(ctx, tx)
 }

wallet/chain/p/client.go

@@ -4,6 +4,8 @@
 package p
 
 import (
+	"time"
+
 	"github.com/ava-labs/avalanchego/vms/platformvm"
 	"github.com/ava-labs/avalanchego/vms/platformvm/txs"
 	"github.com/ava-labs/avalanchego/wallet/chain/p/wallet"
@@ -12,6 +14,8 @@ import (
 
 var _ wallet.Client = (*Client)(nil)
 
+const chainAlias = "P"
+
 func NewClient(
 	c platformvm.Client,
 	b wallet.Backend,
@@ -33,13 +37,15 @@ func (c *Client) IssueTx(
 ) error {
 	ops := common.NewOptions(options)
 	ctx := ops.Context()
+	startTime := time.Now()
 	txID, err := c.client.IssueTx(ctx, tx.Bytes())
+	issuanceDuration := time.Since(startTime)
 	if err != nil {
 		return err
 	}
 
-	if f := ops.PostIssuanceFunc(); f != nil {
-		f(txID)
+	if f := ops.PostIssuanceHandler(); f != nil {
+		f(chainAlias, txID, issuanceDuration)
 	}
 
 	if ops.AssumeDecided() {
@@ -49,6 +55,12 @@ func (c *Client) IssueTx(
 	if err := platformvm.AwaitTxAccepted(c.client, ctx, txID, ops.PollFrequency()); err != nil {
 		return err
 	}
+	totalDuration := time.Since(startTime)
+	issuanceToConfirmationDuration := totalDuration - issuanceDuration
+
+	if f := ops.PostConfirmationHandler(); f != nil {
+		f(chainAlias, txID, totalDuration, issuanceToConfirmationDuration)
+	}
 
 	return c.backend.AcceptTx(ctx, tx)
 }

wallet/chain/x/wallet.go

@@ -4,6 +4,8 @@
 package x
 
 import (
+	"time"
+
 	"github.com/ava-labs/avalanchego/ids"
 	"github.com/ava-labs/avalanchego/vms/avm"
 	"github.com/ava-labs/avalanchego/vms/avm/txs"
@@ -293,13 +295,15 @@ func (w *wallet) IssueTx(
 ) error {
 	ops := common.NewOptions(options)
 	ctx := ops.Context()
+	startTime := time.Now()
 	txID, err := w.client.IssueTx(ctx, tx.Bytes())
+	issuanceDuration := time.Since(startTime)
 	if err != nil {
 		return err
 	}
 
-	if f := ops.PostIssuanceFunc(); f != nil {
-		f(txID)
+	if f := ops.PostIssuanceHandler(); f != nil {
+		f(common.XChainAlias, txID, issuanceDuration)
 	}
 
 	if ops.AssumeDecided() {
@@ -309,6 +313,12 @@ func (w *wallet) IssueTx(
 	if err := avm.AwaitTxAccepted(w.client, ctx, txID, ops.PollFrequency()); err != nil {
 		return err
 	}
+	totalDuration := time.Since(startTime)
+	issuanceToConfirmationDuration := totalDuration - issuanceDuration
+
+	if f := ops.PostConfirmationHandler(); f != nil {
+		f(common.XChainAlias, txID, totalDuration, issuanceToConfirmationDuration)
+	}
 
 	return w.backend.AcceptTx(ctx, tx)
 }

wallet/subnet/primary/common/options.go

@@ -8,18 +8,47 @@ import (
 	"math/big"
 	"time"
 
+	"go.uber.org/zap"
+
 	"github.com/ava-labs/avalanchego/ids"
+	"github.com/ava-labs/avalanchego/utils/logging"
 	"github.com/ava-labs/avalanchego/utils/set"
 	"github.com/ava-labs/avalanchego/vms/secp256k1fx"
 
 	ethcommon "github.com/ethereum/go-ethereum/common"
 )
 
-const defaultPollFrequency = 100 * time.Millisecond
+type PrimaryChainAlias string
+
+const (
+	PChainAlias PrimaryChainAlias = "P"
+	XChainAlias PrimaryChainAlias = "X"
+	CChainAlias PrimaryChainAlias = "C"
 
-// Signature of the function that will be called after a transaction
-// has been issued with the ID of the issued transaction.
-type PostIssuanceFunc func(ids.ID)
+	defaultPollFrequency = 100 * time.Millisecond
+)
+
+// Signature of the function that will be called after a transaction has been issued.
+type TxIssuanceHandler func(
+	// Identifies the primary chain ("P", "X" or "C")
+	chainAlias PrimaryChainAlias,
+	// ID of the confirmed transaction
+	txID ids.ID,
+	// The time from initiation to issuance
+	duration time.Duration,
+)
+
+// Signature of the function that will be called after a transaction has been confirmed.
+type TxConfirmationHandler func(
+	// Identifies the primary chain ("P", "X" or "C")
+	chainAlias PrimaryChainAlias,
+	// ID of the confirmed transaction
+	txID ids.ID,
+	// The time from initiation to confirmation (includes duration of issuance)
+	totalDuration time.Duration,
+	// The time from issuance to confirmation (does not include duration of issuance)
+	issuanceToConfirmationDuration time.Duration,
+)
 
 type Option func(*Options)
 
@@ -48,7 +77,8 @@ type Options struct {
 	pollFrequencySet bool
 	pollFrequency    time.Duration
 
-	postIssuanceFunc PostIssuanceFunc
+	postIssuanceHandler     TxIssuanceHandler
+	postConfirmationHandler TxConfirmationHandler
 }
 
 func NewOptions(ops []Option) *Options {
@@ -132,8 +162,12 @@ func (o *Options) PollFrequency() time.Duration {
 	return defaultPollFrequency
 }
 
-func (o *Options) PostIssuanceFunc() PostIssuanceFunc {
-	return o.postIssuanceFunc
+func (o *Options) PostIssuanceHandler() TxIssuanceHandler {
+	return o.postIssuanceHandler
+}
+
+func (o *Options) PostConfirmationHandler() TxConfirmationHandler {
+	return o.postConfirmationHandler
 }
 
 func WithContext(ctx context.Context) Option {
@@ -200,8 +234,38 @@ func WithPollFrequency(pollFrequency time.Duration) Option {
 	}
 }
 
-func WithPostIssuanceFunc(f PostIssuanceFunc) Option {
+func WithPostIssuanceHandler(f TxIssuanceHandler) Option {
+	return func(o *Options) {
+		o.postIssuanceHandler = f
+	}
+}
+
+func WithPostConfirmationHandler(f TxConfirmationHandler) Option {
+	return func(o *Options) {
+		o.postConfirmationHandler = f
+	}
+}
+
+func WithLoggedIssuranceAndConfirmation(log logging.Logger) Option {
 	return func(o *Options) {
-		o.postIssuanceFunc = f
+		WithPostIssuanceHandler(
+			func(chainAlias PrimaryChainAlias, txID ids.ID, duration time.Duration) {
+				log.Info("issued transaction",
+					zap.String("chainAlias", string(chainAlias)),
+					zap.Stringer("txID", txID),
+					zap.Duration("duration", duration),
+				)
+			},
+		)(o)
+		WithPostConfirmationHandler(
+			func(chainAlias PrimaryChainAlias, txID ids.ID, totalDuration time.Duration, issuanceToConfirmationDuration time.Duration) {
+				log.Info("confirmed transaction",
+					zap.String("chainAlias", string(chainAlias)),
+					zap.Stringer("txID", txID),
+					zap.Duration("totalDuration", totalDuration),
+					zap.Duration("issuanceToConfirmationDuration", issuanceToConfirmationDuration),
+				)
+			},
+		)(o)
 	}
 }