op-node: log mgasps across block building/inserting lifecycle

op-node/rollup/engine/build_seal.go

@@ -113,14 +113,15 @@ 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,
-		Info:        ev.Info,
-		Envelope:    envelope,
-		Ref:         ref,
+		Concluding:   ev.Concluding,
+		DerivedFrom:  ev.DerivedFrom,
+		BuildStarted: ev.BuildStarted,
+		Info:         ev.Info,
+		Envelope:     envelope,
+		Ref:          ref,
 	})
 }

op-node/rollup/engine/build_sealed.go

@@ -1,6 +1,8 @@
 package engine
 
 import (
+	"time"
+
 	"github.com/ethereum-optimism/optimism/op-service/eth"
 )
 
@@ -10,7 +12,8 @@ type BuildSealedEvent struct {
 	// if payload should be promoted to (local) safe (must also be pending safe, see DerivedFrom)
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
-	DerivedFrom eth.L1BlockRef
+	DerivedFrom  eth.L1BlockRef
+	BuildStarted time.Time
 
 	Info     eth.PayloadInfo
 	Envelope *eth.ExecutionPayloadEnvelope
@@ -25,10 +28,11 @@ func (eq *EngDeriver) onBuildSealed(ev BuildSealedEvent) {
 	// If a (pending) safe block, immediately process the block
 	if ev.DerivedFrom != (eth.L1BlockRef{}) {
 		eq.emitter.Emit(PayloadProcessEvent{
-			Concluding:  ev.Concluding,
-			DerivedFrom: ev.DerivedFrom,
-			Envelope:    ev.Envelope,
-			Ref:         ev.Ref,
+			Concluding:   ev.Concluding,
+			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"
@@ -12,7 +13,8 @@ type PayloadProcessEvent struct {
 	// if payload should be promoted to (local) safe (must also be pending safe, see DerivedFrom)
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
-	DerivedFrom eth.L1BlockRef
+	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

@@ -1,14 +1,18 @@
 package engine
 
 import (
+	"time"
+
 	"github.com/ethereum-optimism/optimism/op-service/eth"
 )
 
 type PayloadSuccessEvent struct {
 	// if payload should be promoted to (local) safe (must also be pending safe, see DerivedFrom)
 	Concluding bool
 	// payload is promoted to pending-safe if non-zero
-	DerivedFrom eth.L1BlockRef
+	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

@@ -282,10 +282,11 @@ func (d *Sequencer) onBuildSealed(x engine.BuildSealedEvent) {
 	d.asyncGossip.Gossip(x.Envelope)
 	// Now after having gossiped the block, try to put it in our own canonical chain
 	d.emitter.Emit(engine.PayloadProcessEvent{
-		Concluding:  x.Concluding,
-		DerivedFrom: x.DerivedFrom,
-		Envelope:    x.Envelope,
-		Ref:         x.Ref,
+		Concluding:   x.Concluding,
+		DerivedFrom:  x.DerivedFrom,
+		BuildStarted: x.BuildStarted,
+		Envelope:     x.Envelope,
+		Ref:          x.Ref,
 	})
 	d.latest.Ref = x.Ref
 	d.latestSealed = 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{})
 		}