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

op-node/rollup/engine/build_seal.go

@@ -112,14 +112,18 @@ func (eq *EngDeriver) onBuildSeal(ev BuildSealEvent) {
 	txnCount := len(envelope.ExecutionPayload.Transactions)
 	eq.metrics.CountSequencedTxs(txnCount)
 
-	eq.log.Debug("Processed new L2 block", "l2_unsafe", ref, "l1_origin", ref.L1Origin,
-		"txs", txnCount, "time", ref.Time, "seal_time", sealTime, "build_time", buildTime)
+	eq.log.Debug("Built new L2 block", "l2_unsafe", ref, "l1_origin", ref.L1Origin,
+		"txs", txnCount, "time", ref.Time, "seal_time", sealTime, "build_time", buildTime,
+		"mgas", float64(envelope.ExecutionPayload.GasUsed)/1000000,
+		"mgasps", float64(envelope.ExecutionPayload.GasUsed)*1000/float64(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 (legacy)",
+		"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,7 +204,11 @@ func (ev TryBackupUnsafeReorgEvent) String() string {
 	return "try-backup-unsafe-reorg"
 }
 
-type TryUpdateEngineEvent struct{}
+type TryUpdateEngineEvent struct {
+	BuildStarted  time.Time
+	InsertStarted time.Time
+	Envelope      *eth.ExecutionPayloadEnvelope
+}
 
 func (ev TryUpdateEngineEvent) String() string {
 	return "try-update-engine"
@@ -322,6 +327,40 @@ 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.Envelope != nil {
+				// Create a log: useful for plotting block build/insert time as a way to measure performance.
+				//  - If the TryUpdateEngineEvent.Envelope field is not populated, assume this event is not
+				//    part of a block building/inserting flow and do not log anything
+				fcuFinish := time.Now()
+				logValues := make([]interface{}, 0)
+				payload := x.Envelope.ExecutionPayload
+
+				logValues = append(logValues, "hash", uint64(payload.BlockNumber))
+				logValues = append(logValues, "number", payload.BlockHash)
+				logValues = append(logValues, "state_root", payload.StateRoot)
+				logValues = append(logValues, "timestamp", uint64(payload.Timestamp))
+				logValues = append(logValues, "parent", payload.ParentHash)
+				logValues = append(logValues, "prev_randao", payload.PrevRandao)
+				logValues = append(logValues, "fee_recipient", payload.FeeRecipient)
+				logValues = append(logValues, "txs", len(payload.Transactions))
+
+				var totalTime time.Duration
+				if !x.BuildStarted.IsZero() {
+					totalTime = time.Since(x.BuildStarted)
+					logValues = append(logValues, "build_time", common.PrettyDuration(x.InsertStarted.Sub(x.BuildStarted)))
+					logValues = append(logValues, "insert_time", common.PrettyDuration(fcuFinish.Sub(x.InsertStarted)))
+				} else if !x.InsertStarted.IsZero() {
+					totalTime = time.Since(x.InsertStarted)
+				}
+
+				logValues = append(logValues, "total_time", common.PrettyDuration(totalTime))
+				logValues = append(logValues, "mgas", float64(payload.GasUsed)/1000000)
+				logValues = append(logValues, "mgasps", float64(payload.GasUsed)*1000/float64(totalTime))
+
+				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_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{})
 		}