op-node: revive async block processing timing log (#17915)

* op-node: revive async block processing timing log

* op-node: add clarifying comments to logBlockProcessingMetrics

Author: bitwiseguy

op-node/rollup/engine/payload_success.go

@@ -5,6 +5,7 @@ import (
 	"time"
 
 	"github.com/ethereum-optimism/optimism/op-service/eth"
+	"github.com/ethereum/go-ethereum/common"
 )
 
 type PayloadSuccessEvent struct {
@@ -51,5 +52,47 @@ func (e *EngineController) onPayloadSuccess(ctx context.Context, ev PayloadSucce
 	err := e.tryUpdateEngineInternal(ctx)
 	if err != nil {
 		e.log.Error("Failed to update engine", "error", err)
+	} else {
+		updateEngineFinish := time.Now()
+		e.logBlockProcessingMetrics(updateEngineFinish, ev)
 	}
 }
+
+func (e *EngineController) logBlockProcessingMetrics(updateEngineFinish time.Time, ev PayloadSuccessEvent) {
+	// Protect against nil pointer dereferences
+	if ev.Envelope == nil || ev.Envelope.ExecutionPayload == nil {
+		e.log.Info("Envelope.ExecutionPayload not found, skipping block processing metrics")
+		return
+	}
+
+	mgas := float64(ev.Envelope.ExecutionPayload.GasUsed) / 1e6
+	buildTime := time.Duration(0)
+	insertTime := updateEngineFinish.Sub(ev.InsertStarted)
+	totalTime := insertTime
+
+	// BuildStarted may be zero if sequencer already built + gossiped a block, but failed during
+	// insertion and needed a retry of the insertion. In that case we use the default values above,
+	// otherwise we calculate buildTime and totalTime below
+	if !ev.BuildStarted.IsZero() {
+		buildTime = ev.InsertStarted.Sub(ev.BuildStarted)
+		totalTime = updateEngineFinish.Sub(ev.BuildStarted)
+	}
+
+	// Protect against divide-by-zero
+	var mgasps float64 // Mgas/s
+	if totalTime > 0 {
+		// Calculate "block-processing" Mgas/s.
+		// NOTE: "realtime" mgasps (chain throughput) is a different calculation: (GasUsed / blockPeriod)
+		mgasps = mgas / totalTime.Seconds()
+	}
+
+	e.log.Info("Inserted new L2 unsafe block",
+		"hash", ev.Envelope.ExecutionPayload.BlockHash,
+		"number", uint64(ev.Envelope.ExecutionPayload.BlockNumber),
+		"build_time", common.PrettyDuration(buildTime),
+		"insert_time", common.PrettyDuration(insertTime),
+		"total_time", common.PrettyDuration(totalTime),
+		"mgas", mgas,
+		"mgasps", mgasps,
+	)
+}