op-node: log mgasps across block building/inserting lifecycle (#12907)

* op-node: log mgasps across block processing lifecycle

* op-node: add 'import_time' field to block processing log

* op-node: make log message more descriptive

* op-node: log legacy codepath for InsertUnsafePayload

* op-node: include final ForkchoiceUpdate in block insertion time

* op-node: remove unused BuildTime field from events

* op-node: encapsulate log logic in TryUpdateEngineEvent methods

* op-node: linter fix

* op-node: add comment and adjust sync log wording

* op-node: fix BlockHash, BlockNumber in log

* op-node: seq add BuildStarted to PayloadProcessEvent

* op-node: refactor getBlockProcessingMetrics, protect against divide-by-zero

op-node/rollup/engine/build_seal.go

@@ -113,12 +113,13 @@ func (eq *EngDeriver) onBuildSeal(ev BuildSealEvent) {
 	depositCount, _ := lastDeposit(envelope.ExecutionPayload.Transactions)
 	eq.metrics.CountSequencedTxsInBlock(txnCount, depositCount)
 
-	eq.log.Debug("Processed new L2 block", "l2_unsafe", ref, "l1_origin", ref.L1Origin,
+	eq.log.Debug("Built new L2 block", "l2_unsafe", ref, "l1_origin", ref.L1Origin,
 		"txs", txnCount, "deposits", depositCount, "time", ref.Time, "seal_time", sealTime, "build_time", buildTime)
 
 	eq.emitter.Emit(BuildSealedEvent{
 		Concluding:   ev.Concluding,
 		DerivedFrom:  ev.DerivedFrom,
+		BuildStarted: ev.BuildStarted,
 		Info:         ev.Info,
 		Envelope:     envelope,
 		Ref:          ref,

op-node/rollup/engine/build_sealed.go

 package engine
 
 import (
+	"time"
+
 	"github.com/ethereum-optimism/optimism/op-service/eth"
 )
 
@@ -11,6 +13,7 @@ type BuildSealedEvent struct {
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
 	DerivedFrom  eth.L1BlockRef
+	BuildStarted time.Time
 
 	Info     eth.PayloadInfo
 	Envelope *eth.ExecutionPayloadEnvelope
@@ -29,6 +32,7 @@ func (eq *EngDeriver) onBuildSealed(ev BuildSealedEvent) {
 			DerivedFrom:  ev.DerivedFrom,
 			Envelope:     ev.Envelope,
 			Ref:          ev.Ref,
+			BuildStarted: ev.BuildStarted,
 		})
 	}
 }

op-node/rollup/engine/engine_controller.go

@@ -330,6 +330,7 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et
 		}
 	}
 	// Insert the payload & then call FCU
+	newPayloadStart := time.Now()
 	status, err := e.engine.NewPayload(ctx, envelope.ExecutionPayload, envelope.ParentBeaconBlockRoot)
 	if err != nil {
 		return derive.NewTemporaryError(fmt.Errorf("failed to update insert payload: %w", err))
@@ -342,6 +343,7 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et
 		return derive.NewTemporaryError(fmt.Errorf("cannot process unsafe payload: new - %v; parent: %v; err: %w",
 			payload.ID(), payload.ParentID(), eth.NewPayloadErr(payload, status)))
 	}
+	newPayloadFinish := time.Now()
 
 	// Mark the new payload as valid
 	fc := eth.ForkchoiceState{
@@ -361,6 +363,7 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et
 	}
 	logFn := e.logSyncProgressMaybe()
 	defer logFn()
+	fcu2Start := time.Now()
 	fcRes, err := e.engine.ForkchoiceUpdate(ctx, &fc, nil)
 	if err != nil {
 		var rpcErr rpc.Error
@@ -380,6 +383,7 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et
 		return derive.NewTemporaryError(fmt.Errorf("cannot prepare unsafe chain for new payload: new - %v; parent: %v; err: %w",
 			payload.ID(), payload.ParentID(), eth.ForkchoiceUpdateErr(fcRes.PayloadStatus)))
 	}
+	fcu2Finish := time.Now()
 	e.SetUnsafeHead(ref)
 	e.needFCUCall = false
 	e.emitter.Emit(UnsafeUpdateEvent{Ref: ref})
@@ -397,6 +401,16 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et
 		})
 	}
 
+	totalTime := fcu2Finish.Sub(newPayloadStart)
+	e.log.Info("Inserted new L2 unsafe block (synchronous)",
+		"hash", envelope.ExecutionPayload.BlockHash,
+		"number", uint64(envelope.ExecutionPayload.BlockNumber),
+		"newpayload_time", common.PrettyDuration(newPayloadFinish.Sub(newPayloadStart)),
+		"fcu2_time", common.PrettyDuration(fcu2Finish.Sub(fcu2Start)),
+		"total_time", common.PrettyDuration(totalTime),
+		"mgas", float64(envelope.ExecutionPayload.GasUsed)/1000000,
+		"mgasps", float64(envelope.ExecutionPayload.GasUsed)*1000/float64(totalTime))
+
 	return nil
 }
 

op-node/rollup/engine/events.go

@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"time"
 
+	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/log"
 
 	"github.com/ethereum-optimism/optimism/op-node/rollup"
@@ -203,12 +204,67 @@ func (ev TryBackupUnsafeReorgEvent) String() string {
 	return "try-backup-unsafe-reorg"
 }
 
-type TryUpdateEngineEvent struct{}
+type TryUpdateEngineEvent struct {
+	// These fields will be zero-value (BuildStarted,InsertStarted=time.Time{}, Envelope=nil) if
+	// this event is emitted outside of engineDeriver.onPayloadSuccess
+	BuildStarted  time.Time
+	InsertStarted time.Time
+	Envelope      *eth.ExecutionPayloadEnvelope
+}
 
 func (ev TryUpdateEngineEvent) String() string {
 	return "try-update-engine"
 }
 
+// Checks for the existence of the Envelope field, which is only
+// added by the PayloadSuccessEvent
+func (ev TryUpdateEngineEvent) triggeredByPayloadSuccess() bool {
+	return ev.Envelope != nil
+}
+
+// Returns key/value pairs that can be logged and are useful for plotting
+// block build/insert time as a way to measure performance.
+func (ev TryUpdateEngineEvent) getBlockProcessingMetrics() []interface{} {
+	fcuFinish := time.Now()
+	payload := ev.Envelope.ExecutionPayload
+
+	logValues := []interface{}{
+		"hash", payload.BlockHash,
+		"number", uint64(payload.BlockNumber),
+		"state_root", payload.StateRoot,
+		"timestamp", uint64(payload.Timestamp),
+		"parent", payload.ParentHash,
+		"prev_randao", payload.PrevRandao,
+		"fee_recipient", payload.FeeRecipient,
+		"txs", len(payload.Transactions),
+	}
+
+	var totalTime time.Duration
+	var mgasps float64
+	if !ev.BuildStarted.IsZero() {
+		totalTime = fcuFinish.Sub(ev.BuildStarted)
+		logValues = append(logValues,
+			"build_time", common.PrettyDuration(ev.InsertStarted.Sub(ev.BuildStarted)),
+			"insert_time", common.PrettyDuration(fcuFinish.Sub(ev.InsertStarted)),
+		)
+	} else if !ev.InsertStarted.IsZero() {
+		totalTime = fcuFinish.Sub(ev.InsertStarted)
+	}
+
+	// Avoid divide-by-zero for mgasps
+	if totalTime > 0 {
+		mgasps = float64(payload.GasUsed) * 1000 / float64(totalTime)
+	}
+
+	logValues = append(logValues,
+		"total_time", common.PrettyDuration(totalTime),
+		"mgas", float64(payload.GasUsed)/1000000,
+		"mgasps", mgasps,
+	)
+
+	return logValues
+}
+
 type ForceEngineResetEvent struct {
 	Unsafe, Safe, Finalized eth.L2BlockRef
 }
@@ -322,6 +378,9 @@ func (d *EngDeriver) OnEvent(ev event.Event) bool {
 			} else {
 				d.emitter.Emit(rollup.CriticalErrorEvent{Err: fmt.Errorf("unexpected TryUpdateEngine error type: %w", err)})
 			}
+		} else if x.triggeredByPayloadSuccess() {
+			logValues := x.getBlockProcessingMetrics()
+			d.log.Info("Inserted new L2 unsafe block", logValues...)
 		}
 	case ProcessUnsafePayloadEvent:
 		ref, err := derive.PayloadToBlockRef(d.cfg, x.Envelope.ExecutionPayload)

op-node/rollup/engine/payload_process.go

@@ -3,6 +3,7 @@ package engine
 import (
 	"context"
 	"fmt"
+	"time"
 
 	"github.com/ethereum-optimism/optimism/op-node/rollup"
 	"github.com/ethereum-optimism/optimism/op-service/eth"
@@ -13,6 +14,7 @@ type PayloadProcessEvent struct {
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
 	DerivedFrom  eth.L1BlockRef
+	BuildStarted time.Time
 
 	Envelope *eth.ExecutionPayloadEnvelope
 	Ref      eth.L2BlockRef
@@ -26,6 +28,7 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) {
 	ctx, cancel := context.WithTimeout(eq.ctx, payloadProcessTimeout)
 	defer cancel()
 
+	insertStart := time.Now()
 	status, err := eq.ec.engine.NewPayload(ctx,
 		ev.Envelope.ExecutionPayload, ev.Envelope.ParentBeaconBlockRoot)
 	if err != nil {
@@ -49,7 +52,14 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) {
 		})
 		return
 	case eth.ExecutionValid:
-		eq.emitter.Emit(PayloadSuccessEvent(ev))
+		eq.emitter.Emit(PayloadSuccessEvent{
+			Concluding:    ev.Concluding,
+			DerivedFrom:   ev.DerivedFrom,
+			BuildStarted:  ev.BuildStarted,
+			InsertStarted: insertStart,
+			Envelope:      ev.Envelope,
+			Ref:           ev.Ref,
+		})
 		return
 	default:
 		eq.emitter.Emit(rollup.EngineTemporaryErrorEvent{

op-node/rollup/engine/payload_success.go

 package engine
 
 import (
+	"time"
+
 	"github.com/ethereum-optimism/optimism/op-service/eth"
 )
 
@@ -9,6 +11,8 @@ type PayloadSuccessEvent struct {
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
 	DerivedFrom   eth.L1BlockRef
+	BuildStarted  time.Time
+	InsertStarted time.Time
 
 	Envelope *eth.ExecutionPayloadEnvelope
 	Ref      eth.L2BlockRef
@@ -30,11 +34,9 @@ func (eq *EngDeriver) onPayloadSuccess(ev PayloadSuccessEvent) {
 		})
 	}
 
-	payload := ev.Envelope.ExecutionPayload
-	eq.log.Info("Inserted block", "hash", payload.BlockHash, "number", uint64(payload.BlockNumber),
-		"state_root", payload.StateRoot, "timestamp", uint64(payload.Timestamp), "parent", payload.ParentHash,
-		"prev_randao", payload.PrevRandao, "fee_recipient", payload.FeeRecipient,
-		"txs", len(payload.Transactions), "concluding", ev.Concluding, "derived_from", ev.DerivedFrom)
-
-	eq.emitter.Emit(TryUpdateEngineEvent{})
+	eq.emitter.Emit(TryUpdateEngineEvent{
+		BuildStarted:  ev.BuildStarted,
+		InsertStarted: ev.InsertStarted,
+		Envelope:      ev.Envelope,
+	})
 }

op-node/rollup/sequencing/sequencer.go

@@ -284,6 +284,7 @@ func (d *Sequencer) onBuildSealed(x engine.BuildSealedEvent) {
 	d.emitter.Emit(engine.PayloadProcessEvent{
 		Concluding:   x.Concluding,
 		DerivedFrom:  x.DerivedFrom,
+		BuildStarted: x.BuildStarted,
 		Envelope:     x.Envelope,
 		Ref:          x.Ref,
 	})

op-node/rollup/sequencing/sequencer_chaos_test.go

@@ -216,7 +216,13 @@ func (c *ChaoticEngine) OnEvent(ev event.Event) bool {
 				c.clockRandomIncrement(0, time.Second*3)
 			}
 			c.unsafe = x.Ref
-			c.emitter.Emit(engine.PayloadSuccessEvent(x))
+			c.emitter.Emit(engine.PayloadSuccessEvent{
+				Concluding:   x.Concluding,
+				DerivedFrom:  x.DerivedFrom,
+				BuildStarted: x.BuildStarted,
+				Envelope:     x.Envelope,
+				Ref:          x.Ref,
+			})
 			// With event delay, the engine would update and signal the new forkchoice.
 			c.emitter.Emit(engine.ForkchoiceRequestEvent{})
 		}