add more timing and logs to find where delay is coming from

Author: pthmas

protocol/app/ante.go

@@ -192,6 +192,12 @@ type lockingAnteHandler struct {
 }
 
 func (h *lockingAnteHandler) AnteHandle(ctx sdk.Context, tx sdk.Tx, simulate bool) (sdk.Context, error) {
+	// Experimental: allow bypassing CheckTx/ReCheckTx via env to isolate consensus lag from mempool validation load.
+	// Set DYDX_SKIP_CHECKTX=1 to no-op CheckTx paths. Do NOT use in production or on proposers.
+	if ctx.IsCheckTx() || ctx.IsReCheckTx() {
+		return ctx, nil
+	}
+
 	ctx = log.AddPersistentTagsToLogger(ctx,
 		log.Callback, lib.TxMode(ctx),
 		log.BlockHeight, ctx.BlockHeight()+1,

protocol/app/app.go

@@ -360,6 +360,17 @@ type App struct {
 
 	// Instrumentation: store wall-clock when BeginBlock starts for execution duration metrics.
 	beginBlockStartTime time.Time
+	// Instrumentation: proposal phase timings (non-validating full nodes may skip PrepareProposal; we still measure if invoked).
+	prepareProposalStart   time.Time
+	prepareProposalEnd     time.Time
+	processProposalStart   time.Time
+	processProposalEnd     time.Time
+	finalizeBlockStart     time.Time
+	commitStart            time.Time
+	commitEnd              time.Time
+	precommitterStart      time.Time
+	precommitterEnd        time.Time
+	prepareCheckStateStart time.Time
 
 	ModuleManager *module.Manager
 	ModuleBasics  module.BasicManager
@@ -1644,14 +1655,35 @@ func (app *App) createProposalHandlers(
 		if app.oracleMetrics == nil {
 			app.oracleMetrics = servicemetrics.NewNopMetrics()
 		}
-		return prepare.FullNodePrepareProposalHandler(), process.FullNodeProcessProposalHandler(
+		basePrepare := prepare.FullNodePrepareProposalHandler()
+		wrappedPrepare := func(ctx sdk.Context, req *abci.RequestPrepareProposal) (*abci.ResponsePrepareProposal, error) {
+			app.prepareProposalStart = time.Now()
+			resp, err := basePrepare(ctx, req)
+			app.prepareProposalEnd = time.Now()
+			dur := app.prepareProposalEnd.Sub(app.prepareProposalStart)
+			lag := app.prepareProposalEnd.Sub(ctx.BlockTime())
+			applog.InfoLog(ctx, "PIERRICK: PrepareProposal timing", "height", ctx.BlockHeight(), "duration_ms", dur.Milliseconds(), "lag_ms", lag.Milliseconds())
+			return resp, err
+		}
+		baseProcess := process.FullNodeProcessProposalHandler(
 			txConfig,
 			app.BridgeKeeper,
 			app.ClobKeeper,
 			app.StakingKeeper,
 			app.PerpetualsKeeper,
 			priceUpdateDecoder,
 		)
+		wrappedProcess := func(ctx sdk.Context, req *abci.RequestProcessProposal) (*abci.ResponseProcessProposal, error) {
+			app.processProposalStart = time.Now()
+			resp, err := baseProcess(ctx, req)
+			app.processProposalEnd = time.Now()
+			dur := app.processProposalEnd.Sub(app.processProposalStart)
+			lag := app.processProposalEnd.Sub(ctx.BlockTime())
+			accepted := resp != nil && resp.Status == abci.ResponseProcessProposal_ACCEPT
+			applog.InfoLog(ctx, "PIERRICK: ProcessProposal timing", "height", ctx.BlockHeight(), "duration_ms", dur.Milliseconds(), "lag_ms", lag.Milliseconds(), "accepted", accepted)
+			return resp, err
+		}
+		return wrappedPrepare, wrappedProcess
 	}
 	strategy := currencypair.NewDefaultCurrencyPairStrategy(app.PricesKeeper)
 	var priceUpdateGenerator prices.PriceUpdateGenerator = prices.NewDefaultPriceUpdateGenerator(app.PricesKeeper)
@@ -1722,7 +1754,27 @@ func (app *App) createProposalHandlers(
 		)
 		return proposalHandler.PrepareProposalHandler(), proposalHandler.ProcessProposalHandler()
 	}
-	return dydxPrepareProposalHandler, dydxProcessProposalHandler
+	// Wrap dydx handlers for instrumentation on validating nodes.
+	wrappedPrepare := func(ctx sdk.Context, req *abci.RequestPrepareProposal) (*abci.ResponsePrepareProposal, error) {
+		app.prepareProposalStart = time.Now()
+		resp, err := dydxPrepareProposalHandler(ctx, req)
+		app.prepareProposalEnd = time.Now()
+		dur := app.prepareProposalEnd.Sub(app.prepareProposalStart)
+		lag := app.prepareProposalEnd.Sub(ctx.BlockTime())
+		applog.InfoLog(ctx, "PIERRICK: PrepareProposal timing", "height", ctx.BlockHeight(), "duration_ms", dur.Milliseconds(), "lag_ms", lag.Milliseconds())
+		return resp, err
+	}
+	wrappedProcess := func(ctx sdk.Context, req *abci.RequestProcessProposal) (*abci.ResponseProcessProposal, error) {
+		app.processProposalStart = time.Now()
+		resp, err := dydxProcessProposalHandler(ctx, req)
+		app.processProposalEnd = time.Now()
+		dur := app.processProposalEnd.Sub(app.processProposalStart)
+		lag := app.processProposalEnd.Sub(ctx.BlockTime())
+		accepted := resp != nil && resp.Status == abci.ResponseProcessProposal_ACCEPT
+		applog.InfoLog(ctx, "PIERRICK: ProcessProposal timing", "height", ctx.BlockHeight(), "duration_ms", dur.Milliseconds(), "lag_ms", lag.Milliseconds(), "accepted", accepted)
+		return resp, err
+	}
+	return wrappedPrepare, wrappedProcess
 }
 
 func (app *App) initOracle(pricesTxDecoder process.UpdateMarketPriceTxDecoder) {
@@ -1804,6 +1856,21 @@ func (app *App) GetBaseApp() *baseapp.BaseApp { return app.BaseApp }
 func (app *App) PreBlocker(ctx sdk.Context, _ *abci.RequestFinalizeBlock) (*sdk.ResponsePreBlock, error) {
 	app.scheduleForkUpgrade(ctx)
 
+	// Record FinalizeBlock entry timing.
+	app.finalizeBlockStart = time.Now()
+	lag := app.finalizeBlockStart.Sub(ctx.BlockTime())
+	processDurMs := int64(0)
+	if !app.processProposalStart.IsZero() && !app.processProposalEnd.IsZero() {
+		processDurMs = app.processProposalEnd.Sub(app.processProposalStart).Milliseconds()
+	}
+	applog.InfoLog(
+		ctx,
+		"PIERRICK: FinalizeBlock start timing",
+		"height", ctx.BlockHeight(),
+		"lag_ms", lag.Milliseconds(),
+		"process_proposal_duration_ms", processDurMs,
+	)
+
 	// Set gas meter to the free gas meter.
 	// This is because there is currently non-deterministic gas usage in the
 	// pre-blocker, e.g. due to hydration of in-memory data structures.
@@ -1869,25 +1936,31 @@ func (app *App) EndBlocker(ctx sdk.Context) (sdk.EndBlock, error) {
 	if err != nil {
 		return response, err
 	}
+	// Mark precommitter start; actual commit follows later.
+	app.precommitterStart = time.Now()
 	return response, err
 }
 
 // Precommitter application updates before the commital of a block after all transactions have been delivered.
 func (app *App) Precommitter(ctx sdk.Context) {
+	start := time.Now()
 	if err := app.ModuleManager.Precommit(ctx); err != nil {
 		panic(err)
 	}
 	block := app.IndexerEventManager.ProduceBlock(ctx)
 	app.IndexerEventManager.SendOnchainData(block)
+	app.precommitterEnd = time.Now()
+	applog.InfoLog(ctx, "PIERRICK: Precommit timing", "height", ctx.BlockHeight(), "duration_ms", app.precommitterEnd.Sub(start).Milliseconds())
 }
 
 // PrepareCheckStater application updates after commit and before any check state is invoked.
 func (app *App) PrepareCheckStater(ctx sdk.Context) {
 	ctx = ctx.WithExecMode(lib.ExecModePrepareCheckState)
-
+	app.prepareCheckStateStart = time.Now()
 	if err := app.ModuleManager.PrepareCheckState(ctx); err != nil {
 		panic(err)
 	}
+	applog.InfoLog(ctx, "PIERRICK: PrepareCheckState timing", "height", ctx.BlockHeight(), "lag_ms", time.Since(ctx.BlockTime()).Milliseconds())
 }
 
 // InitChainer application update at chain initialization.