log and stress-test improvements

0xPolygon · Feb 18, 2025 · 6399185 · 6399185
1 parent 71fc9a9
commit 6399185
Show file tree

Hide file tree

Showing 2 changed files with 13 additions and 9 deletions.
diff --git a/app/abci.go b/app/abci.go
@@ -35,6 +35,7 @@ func (app *HeimdallApp) NewPrepareProposalHandler() sdk.PrepareProposalHandler {
 	return func(ctx sdk.Context, req *abci.RequestPrepareProposal) (*abci.ResponsePrepareProposal, error) {
 		logger := app.Logger()
 		start := time.Now()
+		logger.Info("🕒 Start PrepareProposal:", "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 
 		if err := ValidateVoteExtensions(ctx, req.Height, req.ProposerAddress, req.LocalLastCommit.Votes, req.LocalLastCommit.Round, app.StakeKeeper); err != nil {
 			logger.Error("Error occurred while validating VEs in PrepareProposal", err)
@@ -154,7 +155,7 @@ func (app *HeimdallApp) NewPrepareProposalHandler() sdk.PrepareProposalHandler {
 
 		duration := time.Since(start)
 		formatted := fmt.Sprintf("%.6fms", float64(duration)/float64(time.Millisecond))
-		logger.Info("🕒 PrepareProposal:" + formatted)
+		logger.Info("🕒 End PrepareProposal:", "duration", formatted, "height", req.Height, "payloadSize", len(txs[0]), "momentTime", time.Now().Format("04:05.000000"))
 		return &abci.ResponsePrepareProposal{Txs: txs}, nil
 	}
 }
@@ -165,6 +166,7 @@ func (app *HeimdallApp) NewProcessProposalHandler() sdk.ProcessProposalHandler {
 	return func(ctx sdk.Context, req *abci.RequestProcessProposal) (*abci.ResponseProcessProposal, error) {
 		logger := app.Logger()
 		start := time.Now()
+		logger.Info("🕒 Start ProcessProposal:", "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 
 		// check if there are any txs in the request
 		if len(req.Txs) < 1 {
@@ -250,7 +252,7 @@ func (app *HeimdallApp) NewProcessProposalHandler() sdk.ProcessProposalHandler {
 
 		duration := time.Since(start)
 		formatted := fmt.Sprintf("%.6fms", float64(duration)/float64(time.Millisecond))
-		logger.Info("🕒 ProcessProposal:" + formatted)
+		logger.Info("🕒 End ProcessProposal:", "duration", formatted, "height", req.Height, "payloadSize", len(req.Txs[0]), "momentTime", time.Now().Format("04:05.000000"))
 		return &abci.ResponseProcessProposal{Status: abci.ResponseProcessProposal_ACCEPT}, nil
 	}
 }
@@ -261,6 +263,7 @@ func (app *HeimdallApp) ExtendVoteHandler() sdk.ExtendVoteHandler {
 		logger := app.Logger()
 		logger.Debug("Extending Vote!", "height", ctx.BlockHeight())
 		start := time.Now()
+		logger.Info("🕒 Start ExtendVote:", "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 
 		// check if VEs are enabled
 		if err := checkIfVoteExtensionsDisabled(ctx, req.Height); err != nil {
@@ -366,7 +369,7 @@ func (app *HeimdallApp) ExtendVoteHandler() sdk.ExtendVoteHandler {
 
 		duration := time.Since(start)
 		formatted := fmt.Sprintf("%.6fms", float64(duration)/float64(time.Millisecond))
-		logger.Info("🕒 ExtendVote:" + formatted)
+		logger.Info("🕒 End ExtendVote:", "duration", formatted, "height", req.Height, "payloadSize", len(req.Txs[0]), "momentTime", time.Now().Format("04:05.000000"))
 		return &abci.ResponseExtendVote{VoteExtension: bz, NonRpExtension: nonRpVoteExt}, nil
 	}
 }
@@ -377,6 +380,7 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 		logger := app.Logger()
 		logger.Debug("Verifying vote extension", "height", ctx.BlockHeight())
 		start := time.Now()
+		logger.Info("🕒 Start VerifyVote:", "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 
 		// check if VEs are enabled
 		if err := checkIfVoteExtensionsDisabled(ctx, req.Height); err != nil {
@@ -422,7 +426,7 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 
 		duration := time.Since(start)
 		formatted := fmt.Sprintf("%.6fms", float64(duration)/float64(time.Millisecond))
-		logger.Info("🕒 VerifyVote:" + formatted)
+		logger.Info("🕒 End VerifyVote:", "duration", formatted, "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 		return &abci.ResponseVerifyVoteExtension{Status: abci.ResponseVerifyVoteExtension_ACCEPT}, nil
 	}
 }
@@ -431,6 +435,7 @@ func (app *HeimdallApp) VerifyVoteExtensionHandler() sdk.VerifyVoteExtensionHand
 func (app *HeimdallApp) PreBlocker(ctx sdk.Context, req *abci.RequestFinalizeBlock) (*sdk.ResponsePreBlock, error) {
 	logger := app.Logger()
 	start := time.Now()
+	logger.Info("🕒 Start PreBlocker:", "height", req.Height, "momentTime", time.Now().Format("04:05.000000"))
 
 	if err := checkIfVoteExtensionsDisabled(ctx, req.Height+1); err != nil {
 		return nil, err
@@ -603,7 +608,7 @@ func (app *HeimdallApp) PreBlocker(ctx sdk.Context, req *abci.RequestFinalizeBlo
 	}
 	duration := time.Since(start)
 	formatted := fmt.Sprintf("%.6fms", float64(duration)/float64(time.Millisecond))
-	logger.Info("🕒 PreBlocker:" + formatted)
+	logger.Info("🕒 End PreBlocker:", "duration", formatted, "height", req.Height, "payloadSize", len(req.Txs[0]), "momentTime", time.Now().Format("04:05.000000"))
 	return app.ModuleManager.PreBlock(ctx)
 }
 

diff --git a/engine-api-poc/run_test.sh b/engine-api-poc/run_test.sh
@@ -9,9 +9,8 @@ mnemonics=(
 )
 
 folder="./engine-api-poc/test-output"
-if [ ! -d "$folder" ]; then
-  mkdir "$folder"
-fi
+rm -rf "$folder"
+mkdir "$folder"
 
 echo "Starting pandoras-box processes..."
 
@@ -29,7 +28,7 @@ for iteration in {1..10}; do
     # Run pandoras-box, writing its output to a temporary file
     pandoras-box -url "http://localhost:${port}" \
       -m "$mnemonic" \
-      -t 100 -b 500 -o "$temp_file" > /dev/null 2>&1 &
+      -t 200 -b 50 -o "$temp_file" > /dev/null 2>&1 &
 
     pid=$!
     echo "Started pandoras-box on port $port with PID: $pid"