diff --git a/internal/ethapi/api_mev.go b/internal/ethapi/api_mev.go index 9f0031725e..b1e0c08605 100644 --- a/internal/ethapi/api_mev.go +++ b/internal/ethapi/api_mev.go @@ -4,6 +4,7 @@ import ( "context" "fmt" "math/big" + "time" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/core/types" @@ -25,6 +26,7 @@ func NewMevAPI(b Backend) *MevAPI { // If mev is not running or bid is invalid, return error. // Otherwise, creates a builder bid for the given argument, submit it to the miner. func (m *MevAPI) SendBid(ctx context.Context, args types.BidArgs) (common.Hash, error) { + ctx = context.WithValue(ctx, "receiveTime", time.Now().UnixMilli()) if !m.b.MevRunning() { return common.Hash{}, types.ErrMevNotRunning } diff --git a/miner/bid_simulator.go b/miner/bid_simulator.go index bc5090df73..d4c3412565 100644 --- a/miner/bid_simulator.go +++ b/miner/bid_simulator.go @@ -32,7 +32,14 @@ import ( ) var ( - bidSimTimer = metrics.NewRegisteredTimer("bid/sim/duration", nil) + bidPreCheckTimer = metrics.NewRegisteredTimer("bid/preCheck", nil) + bidTryInterruptTimer = metrics.NewRegisteredTimer("bid/sim/tryInterrupt", nil) + bidSim1stBidTimer = metrics.NewRegisteredTimer("bid/sim/sim1stBid", nil) + bidSimTimer = metrics.NewRegisteredTimer("bid/sim/duration", nil) + + simulateSpeedGauge = metrics.NewRegisteredGauge("bid/sim/simulateSpeed", nil) // Mps + + bidSimTimeoutCounter = metrics.NewRegisteredCounter("bid/sim/simTimeout", nil) ) var ( @@ -71,8 +78,9 @@ type simBidReq struct { // newBidPackage is the warp of a new bid and a feedback channel type newBidPackage struct { - bid *types.Bid - feedback chan error + bid *types.Bid + feedback chan error + receiveTime int64 } // bidSimulator is in charge of receiving bid from builders, reporting issue to builders. @@ -455,6 +463,7 @@ func (b *bidSimulator) newBidLoop() { blockInterval := b.getBlockInterval(parentHeader) blockTime := parentHeader.MilliTimestamp() + blockInterval left := time.Until(time.UnixMilli(int64(blockTime))) + bidTryInterruptTimer.UpdateSince(time.UnixMilli(newBid.receiveTime)) if b.canBeInterrupted(blockTime) { log.Debug("simulate in progress, interrupt", "blockTime", blockTime, "left", left.Milliseconds(), @@ -571,14 +580,21 @@ func (b *bidSimulator) clearLoop() { // sendBid checks if the bid is already exists or if the builder sends too many bids, // if yes, return error, if not, add bid into newBid chan waiting for judge profit. -func (b *bidSimulator) sendBid(_ context.Context, bid *types.Bid) error { +func (b *bidSimulator) sendBid(ctx context.Context, bid *types.Bid) error { timer := time.NewTimer(1 * time.Second) defer timer.Stop() replyCh := make(chan error, 1) + receiveTime, ok := ctx.Value("receiveTime").(int64) + if ok { + bidPreCheckTimer.UpdateSince(time.UnixMilli(receiveTime)) + } else { + receiveTime = time.Now().UnixMilli() + } + select { - case b.newBidCh <- newBidPackage{bid: bid, feedback: replyCh}: + case b.newBidCh <- newBidPackage{bid: bid, feedback: replyCh, receiveTime: receiveTime}: b.AddPending(bid.BlockNumber, bid.Builder, bid.Hash()) case <-timer.C: return types.ErrMevBusy @@ -654,6 +670,7 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { "blockNumber", blockNumber, "parentHash", parentHash, "builder", builder, + "bidHash", bidRuntime.bid.Hash().Hex(), "gasUsed", bidRuntime.bid.GasUsed, "simElapsed", time.Since(simStart), } @@ -704,8 +721,7 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { // if the left time is not enough to do simulation, return delay := b.engine.Delay(b.chain, bidRuntime.env.header, &b.delayLeftOver) if delay == nil || *delay <= 0 { - log.Info("BidSimulator: abort commit, not enough time to simulate", - "builder", bidRuntime.bid.Builder, "bidHash", bidRuntime.bid.Hash().Hex()) + log.Info("BidSimulator: abort commit, no time to begin simulating") return } @@ -734,6 +750,10 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { return } + if len(b.bidsToSim[bidRuntime.bid.BlockNumber]) == 1 { + bidSim1stBidTimer.UpdateSince(time.UnixMilli(int64(b.chain.GetHeaderByHash(bidRuntime.bid.ParentHash).MilliTimestamp()))) + } + // commit transactions in bid for _, tx := range bidRuntime.bid.Txs { select { @@ -760,6 +780,14 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { } } + // check whether time `NoInterruptLeftOver-delayLeftOver` is enough for simulating + delay = b.engine.Delay(b.chain, bidRuntime.env.header, &b.delayLeftOver) + if delay != nil && *delay < 0 { + bidSimTimeoutCounter.Inc(1) + log.Info("BidSimulator: fail to commit, timeout when simulating completed") + return + } + // check if bid reward is valid { bidRuntime.packReward(*b.config.ValidatorCommission) @@ -809,11 +837,13 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { } // if enable greedy merge, fill bid env with transactions from mempool + greedyMergeElapsed := time.Duration(0) if *b.config.GreedyMergeTx { endingBidsExtra := 20 * time.Millisecond // Add a buffer to ensure ending bids before `delayLeftOver` minTimeLeftForEndingBids := b.delayLeftOver + endingBidsExtra delay := b.engine.Delay(b.chain, bidRuntime.env.header, &minTimeLeftForEndingBids) if delay != nil && *delay > 0 { + greedyMergeStartTs := time.Now() bidTxsSet := mapset.NewThreadUnsafeSetWithSize[common.Hash](len(bidRuntime.bid.Txs)) for _, tx := range bidRuntime.bid.Txs { bidTxsSet.Add(tx.Hash()) @@ -821,11 +851,13 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { stopTimer := time.NewTimer(*delay) defer stopTimer.Stop() fillErr := b.bidWorker.fillTransactions(interruptCh, bidRuntime.env, stopTimer, bidTxsSet) - log.Trace("BidSimulator: greedy merge stopped", "block", bidRuntime.env.header.Number, - "builder", bidRuntime.bid.Builder, "tx count", bidRuntime.env.tcount-bidTxLen+1, "err", fillErr) // recalculate the packed reward bidRuntime.packReward(*b.config.ValidatorCommission) + greedyMergeElapsed = time.Since(greedyMergeStartTs) + + log.Debug("BidSimulator: greedy merge stopped", "block", bidRuntime.env.header.Number, + "builder", bidRuntime.bid.Builder, "tx count", bidRuntime.env.tcount-bidTxLen+1, "err", fillErr, "greedyMergeElapsed", greedyMergeElapsed) } } @@ -840,9 +872,10 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { } bestBid := b.GetBestBid(parentHash) + simElapsed := time.Since(startTS) if bestBid == nil { winResult := "true[first]" - log.Info("[BID RESULT]", "win", winResult, "builder", bidRuntime.bid.Builder, "hash", bidRuntime.bid.Hash().TerminalString(), "simElapsed", time.Since(startTS)) + log.Info("[BID RESULT]", "win", winResult, "builder", bidRuntime.bid.Builder, "hash", bidRuntime.bid.Hash().TerminalString(), "simElapsed", simElapsed) } else if bidRuntime.bid.Hash() != bestBid.bid.Hash() { // skip log flushing when only one bid is present log.Info("[BID RESULT]", "win", bidRuntime.packedBlockReward.Cmp(bestBid.packedBlockReward) > 0, @@ -856,9 +889,16 @@ func (b *bidSimulator) simBid(interruptCh chan int32, bidRuntime *BidRuntime) { "bidBlockTx", bidRuntime.env.tcount, "bestBlockTx", bestBid.env.tcount, - "simElapsed", time.Since(startTS), + "simElapsed", simElapsed, ) } + const minGasForSpeedMetric = 30_000_000 + if bidRuntime.bid.GasUsed > minGasForSpeedMetric { + timeCostMs := (simElapsed - greedyMergeElapsed).Microseconds() + if timeCostMs > 0 { + simulateSpeedGauge.Update(int64(float64(bidRuntime.bid.GasUsed) / float64(timeCostMs) / 1000)) + } + } // this is the simplest strategy: best for all the delegators. if bestBid == nil || bidRuntime.packedBlockReward.Cmp(bestBid.packedBlockReward) > 0 { diff --git a/miner/miner_mev.go b/miner/miner_mev.go index ea510ce790..102d8e4381 100644 --- a/miner/miner_mev.go +++ b/miner/miner_mev.go @@ -67,7 +67,7 @@ func (miner *Miner) SendBid(ctx context.Context, bidArgs *types.BidArgs) (common timeout := time.Until(bidBetterBefore) if timeout <= 0 { - return common.Hash{}, fmt.Errorf("too late, expected befor %s, appeared %s later", bidBetterBefore, + return common.Hash{}, fmt.Errorf("too late, expected before %s, appeared %s later", bidBetterBefore, common.PrettyDuration(timeout)) }