tools: block-generator locked table retry and additional metrics

tools/block-generator/generator/generate.go

@@ -17,7 +17,6 @@
 package generator
 
 import (
-	_ "embed"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -32,49 +31,19 @@ import (
 	"github.com/algorand/go-algorand/data/basics"
 	"github.com/algorand/go-algorand/data/bookkeeping"
 	txn "github.com/algorand/go-algorand/data/transactions"
-	"github.com/algorand/go-algorand/data/transactions/logic"
 	"github.com/algorand/go-algorand/ledger/ledgercore"
 	"github.com/algorand/go-algorand/logging"
 	"github.com/algorand/go-algorand/protocol"
 	"github.com/algorand/go-algorand/rpcs"
-	"github.com/algorand/go-algorand/tools/block-generator/util"
 )
 
-// ---- templates ----
-
-//go:embed teal/poap_boxes.teal
-var approvalBoxes string
-var approvalBoxesBytes interface{}
-
-//go:embed teal/poap_clear.teal
-var clearBoxes string
-var clearBoxesBytes interface{}
-
-//go:embed teal/swap_amm.teal
-var approvalSwap string
-var approvalSwapBytes interface{}
-
-//go:embed teal/swap_clear.teal
-var clearSwap string
-var clearSwapBytes interface{}
-
-func init() {
-	prog, err := logic.AssembleString(approvalBoxes)
-	util.MaybeFail(err, "failed to assemble approval program")
-	approvalBoxesBytes = prog.Program
-
-	prog, err = logic.AssembleString(clearBoxes)
-	util.MaybeFail(err, "failed to assemble clear program")
-	clearBoxesBytes = prog.Program
-
-	prog, err = logic.AssembleString(approvalSwap)
-	util.MaybeFail(err, "failed to assemble approvalSwap program")
-	approvalSwapBytes = prog.Program
-
-	prog, err = logic.AssembleString(clearSwap)
-	util.MaybeFail(err, "failed to assemble clearSwap program")
-	clearSwapBytes = prog.Program
-}
+const (
+	BlockTotalSizeBytes    = "blocks_total_size_bytes"
+	CommitWaitTimeMS       = "commit_wait_time_ms"
+	BlockgenGenerateTimeMS = "blockgen_generate_time_ms"
+	LedgerEvalTimeMS       = "ledger_eval_time_ms"
+	LedgerValidateTimeMS   = "ledger_validate_time_ms"
+)
 
 // ---- constructors ----
 
@@ -105,10 +74,11 @@ func MakeGenerator(log logging.Logger, dbround uint64, bkGenesis bookkeeping.Gen
 		rewardsResidue:            0,
 		rewardsRate:               0,
 		rewardsRecalculationRound: 0,
-		reportData:                make(map[TxTypeID]TxData),
 		latestData:                make(map[TxTypeID]uint64),
 		roundOffset:               dbround,
 	}
+	gen.reportData.Transactions = make(map[TxTypeID]TxData)
+	gen.reportData.Counters = make(map[string]uint64)
 
 	gen.feeSink[31] = 1
 	gen.rewardsPool[31] = 2
@@ -357,7 +327,7 @@ func (g *generator) WriteBlock(output io.Writer, round uint64) error {
 		g.setBlockHeader(&cert)
 
 		intra := uint64(0)
-		txGroupsAD := [][]txn.SignedTxnWithAD{}
+		var txGroupsAD [][]txn.SignedTxnWithAD
 		for intra < minTxnsForBlock {
 			txGroupAD, numTxns, err := g.generateTxGroup(g.round, intra)
 			if err != nil {
@@ -371,21 +341,25 @@ func (g *generator) WriteBlock(output io.Writer, round uint64) error {
 			intra += numTxns
 		}
 		generated = time.Now()
+		g.reportData.Counters[BlockgenGenerateTimeMS] += uint64(generated.Sub(start).Milliseconds())
 
-		vBlock, ledgerTxnCount, err := g.evaluateBlock(cert.Block.BlockHeader, txGroupsAD, int(intra))
+		vBlock, ledgerTxnCount, commitWaitTime, err := g.evaluateBlock(cert.Block.BlockHeader, txGroupsAD, int(intra))
 		if err != nil {
 			return fmt.Errorf("failed to evaluate block: %w", err)
 		}
 		if ledgerTxnCount != g.txnCounter+intra {
 			return fmt.Errorf("evaluateBlock() txn count mismatches theoretical intra: %d != %d", ledgerTxnCount, g.txnCounter+intra)
 		}
 		evaluated = time.Now()
+		g.reportData.Counters[LedgerEvalTimeMS] += uint64(evaluated.Sub(generated).Milliseconds())
 
 		err = g.ledger.AddValidatedBlock(*vBlock, cert.Certificate)
 		if err != nil {
 			return fmt.Errorf("failed to add validated block: %w", err)
 		}
 		validated = time.Now()
+		g.reportData.Counters[CommitWaitTimeMS] += uint64(commitWaitTime.Milliseconds())
+		g.reportData.Counters[LedgerValidateTimeMS] += uint64((validated.Sub(evaluated) - commitWaitTime).Milliseconds())
 
 		cert.Block.Payset = vBlock.Block().Payset
 
@@ -400,6 +374,8 @@ func (g *generator) WriteBlock(output io.Writer, round uint64) error {
 
 	// write the msgpack bytes for a block
 	g.latestBlockMsgp = protocol.EncodeMsgp(&cert)
+	g.reportData.Counters[BlockTotalSizeBytes] += uint64(len(g.latestBlockMsgp))
+
 	_, err = output.Write(g.latestBlockMsgp)
 	if err != nil {
 		return err
@@ -812,7 +788,7 @@ func (g *generator) generateAssetTxnInternalHint(txType TxTypeID, round uint64,
 	}
 
 	if g.balances[senderIndex] < txn.Fee.ToUint64() {
-		fmt.Printf("\n\nthe sender account does not have enough algos for the transfer. idx %d, asset transaction type %v, num %d\n\n", senderIndex, actual, g.reportData[actual].GenerationCount)
+		fmt.Printf("\n\nthe sender account does not have enough algos for the transfer. idx %d, asset transaction type %v, num %d\n\n", senderIndex, actual, g.reportData.Transactions[actual].GenerationCount)
 		os.Exit(1)
 	}
 
@@ -835,10 +811,10 @@ func track(id TxTypeID) (TxTypeID, time.Time) {
 
 func (g *generator) recordData(id TxTypeID, start time.Time) {
 	g.latestData[id]++
-	data := g.reportData[id]
+	data := g.reportData.Transactions[id]
 	data.GenerationCount += 1
 	data.GenerationTime += time.Since(start)
-	g.reportData[id] = data
+	g.reportData.Transactions[id] = data
 }
 
 // ---- sign transactions ----

tools/block-generator/generator/generate_apps.go

@@ -17,13 +17,53 @@
 package generator
 
 import (
+	_ "embed"
 	"fmt"
 	"math/rand"
 	"time"
 
 	txn "github.com/algorand/go-algorand/data/transactions"
+	"github.com/algorand/go-algorand/data/transactions/logic"
+	"github.com/algorand/go-algorand/tools/block-generator/util"
 )
 
+// ---- templates ----
+
+//go:embed teal/poap_boxes.teal
+var approvalBoxes string
+var approvalBoxesBytes interface{}
+
+//go:embed teal/poap_clear.teal
+var clearBoxes string
+var clearBoxesBytes interface{}
+
+//go:embed teal/swap_amm.teal
+var approvalSwap string
+var approvalSwapBytes interface{}
+
+//go:embed teal/swap_clear.teal
+var clearSwap string
+var clearSwapBytes interface{}
+
+// Precompile teal programs
+func init() {
+	prog, err := logic.AssembleString(approvalBoxes)
+	util.MaybeFail(err, "failed to assemble approval program")
+	approvalBoxesBytes = prog.Program
+
+	prog, err = logic.AssembleString(clearBoxes)
+	util.MaybeFail(err, "failed to assemble clear program")
+	clearBoxesBytes = prog.Program
+
+	prog, err = logic.AssembleString(approvalSwap)
+	util.MaybeFail(err, "failed to assemble approvalSwap program")
+	approvalSwapBytes = prog.Program
+
+	prog, err = logic.AssembleString(clearSwap)
+	util.MaybeFail(err, "failed to assemble clearSwap program")
+	clearSwapBytes = prog.Program
+}
+
 // ---- generator app state ----
 
 func (g *generator) resetPendingApps() {
@@ -69,9 +109,10 @@ func countEffects(actual TxTypeID) uint64 {
 	return cnt
 }
 
+// TODO: Can this be removed? The inner txns are already marked as "inner" so no nened to aggregate them.
 func CumulativeEffects(report Report) EffectsReport {
 	effsReport := make(EffectsReport)
-	for txType, data := range report {
+	for txType, data := range report.Transactions {
 		rootCount := data.GenerationCount
 		effsReport[string(txType)] += rootCount
 		for _, effect := range effects[txType] {

tools/block-generator/generator/generate_test.go

@@ -674,16 +674,16 @@ func TestRecordData(t *testing.T) {
 	gen := makePrivateGenerator(t, 0, bookkeeping.Genesis{})
 
 	id := TxTypeID("test")
-	data, ok := gen.reportData[id]
+	data, ok := gen.reportData.Transactions[id]
 	require.False(t, ok)
 
 	gen.recordData(id, time.Now())
-	data, ok = gen.reportData[id]
+	data, ok = gen.reportData.Transactions[id]
 	require.True(t, ok)
 	require.Equal(t, uint64(1), data.GenerationCount)
 
 	gen.recordData(id, time.Now())
-	data, ok = gen.reportData[id]
+	data, ok = gen.reportData.Transactions[id]
 	require.True(t, ok)
 	require.Equal(t, uint64(2), data.GenerationCount)
 }
@@ -725,11 +725,13 @@ func TestCumulativeEffects(t *testing.T) {
 	partitiontest.PartitionTest(t)
 
 	report := Report{
-		TxTypeID("app_boxes_optin"):   {GenerationCount: uint64(42)},
-		TxTypeID("app_boxes_create"):  {GenerationCount: uint64(1337)},
-		TxTypeID("pay_pay"):           {GenerationCount: uint64(999)},
-		TxTypeID("asset_optin_total"): {GenerationCount: uint64(13)},
-		TxTypeID("app_boxes_call"):    {GenerationCount: uint64(413)},
+		Transactions: map[TxTypeID]TxData{
+			TxTypeID("app_boxes_optin"):   {GenerationCount: uint64(42)},
+			TxTypeID("app_boxes_create"):  {GenerationCount: uint64(1337)},
+			TxTypeID("pay_pay"):           {GenerationCount: uint64(999)},
+			TxTypeID("asset_optin_total"): {GenerationCount: uint64(13)},
+			TxTypeID("app_boxes_call"):    {GenerationCount: uint64(413)},
+		},
 	}
 
 	expectedEffectsReport := EffectsReport{

tools/block-generator/generator/generator_ledger.go

@@ -20,6 +20,8 @@ import (
 	"encoding/binary"
 	"fmt"
 	"os"
+	"strings"
+	"time"
 
 	"github.com/algorand/avm-abi/apps"
 	cconfig "github.com/algorand/go-algorand/config"
@@ -167,19 +169,30 @@ func (g *generator) startEvaluator(hdr bookkeeping.BlockHeader, paysetHint int)
 		})
 }
 
-func (g *generator) evaluateBlock(hdr bookkeeping.BlockHeader, txGroups [][]txn.SignedTxnWithAD, paysetHint int) (*ledgercore.ValidatedBlock, uint64 /* txnCount */, error) {
+func (g *generator) evaluateBlock(hdr bookkeeping.BlockHeader, txGroups [][]txn.SignedTxnWithAD, paysetHint int) (*ledgercore.ValidatedBlock, uint64 /* txnCount */, time.Duration /* commit wait time */, error) {
+	commitWaitTime := time.Duration(0)
+	waitDelay := 10 * time.Millisecond
 	eval, err := g.startEvaluator(hdr, paysetHint)
 	if err != nil {
-		return nil, 0, fmt.Errorf("could not start evaluator: %w", err)
+		return nil, 0, 0, fmt.Errorf("could not start evaluator: %w", err)
 	}
 	for i, txGroup := range txGroups {
-		err := eval.TransactionGroup(txGroup)
-		if err != nil {
-			return nil, 0, fmt.Errorf("could not evaluate transaction group %d: %w", i, err)
+		for {
+			err := eval.TransactionGroup(txGroup)
+			if err != nil {
+				if strings.Contains(err.Error(), "database table is locked") {
+					time.Sleep(waitDelay)
+					commitWaitTime += waitDelay
+					// sometimes the database is locked, so we retry
+					continue
+				}
+				return nil, 0, 0, fmt.Errorf("could not evaluate transaction group %d: %w", i, err)
+			}
+			break
 		}
 	}
 	lvb, err := eval.GenerateBlock()
-	return lvb, eval.TestingTxnCounter(), err
+	return lvb, eval.TestingTxnCounter(), commitWaitTime, err
 }
 
 func countInners(ad txn.ApplyData) int {

tools/block-generator/generator/generator_types.go

@@ -149,7 +149,10 @@ type assetHolding struct {
 }
 
 // Report is the generation report.
-type Report map[TxTypeID]TxData
+type Report struct {
+	Counters     map[string]uint64   `json:"counters"`
+	Transactions map[TxTypeID]TxData `json:"transactions"`
+}
 
 // EffectsReport collates transaction counts caused by a root transaction.
 type EffectsReport map[string]uint64