From d7906bbdbbf6140473ac94de068a309cb72ec47e Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Tue, 12 Nov 2024 16:13:41 -0500 Subject: [PATCH 01/12] op-node: log mgasps across block processing lifecycle --- op-node/rollup/engine/build_seal.go | 16 ++++++++++------ op-node/rollup/engine/build_sealed.go | 14 +++++++++----- op-node/rollup/engine/payload_process.go | 4 +++- op-node/rollup/engine/payload_success.go | 10 ++++++++-- 4 files changed, 30 insertions(+), 14 deletions(-) diff --git a/op-node/rollup/engine/build_seal.go b/op-node/rollup/engine/build_seal.go index b292681e13f..99a7e63c9c1 100644 --- a/op-node/rollup/engine/build_seal.go +++ b/op-node/rollup/engine/build_seal.go @@ -113,13 +113,17 @@ func (eq *EngDeriver) onBuildSeal(ev BuildSealEvent) { 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) + "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, }) } diff --git a/op-node/rollup/engine/build_sealed.go b/op-node/rollup/engine/build_sealed.go index eb2680850a7..5ceff489ecc 100644 --- a/op-node/rollup/engine/build_sealed.go +++ b/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, }) } } diff --git a/op-node/rollup/engine/payload_process.go b/op-node/rollup/engine/payload_process.go index 62d7ded47f0..c6b1e542c6d 100644 --- a/op-node/rollup/engine/payload_process.go +++ b/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 diff --git a/op-node/rollup/engine/payload_success.go b/op-node/rollup/engine/payload_success.go index c00d8e81ea7..35a1e374dc0 100644 --- a/op-node/rollup/engine/payload_success.go +++ b/op-node/rollup/engine/payload_success.go @@ -1,6 +1,8 @@ package engine import ( + "time" + "github.com/ethereum-optimism/optimism/op-service/eth" ) @@ -8,7 +10,8 @@ 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 Envelope *eth.ExecutionPayloadEnvelope Ref eth.L2BlockRef @@ -30,11 +33,14 @@ func (eq *EngDeriver) onPayloadSuccess(ev PayloadSuccessEvent) { }) } + elapsed := time.Since(ev.BuildStarted) 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) + "txs", len(payload.Transactions), "concluding", ev.Concluding, "derived_from", ev.DerivedFrom, + "elapsed", elapsed, "mgas", float64(payload.GasUsed)/1000000, + "mgasps", float64(payload.GasUsed)*1000/float64(elapsed)) eq.emitter.Emit(TryUpdateEngineEvent{}) } From 492a1d259dbefa4d5e12a0412c225eeb3f33d1f3 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Wed, 13 Nov 2024 11:27:55 -0500 Subject: [PATCH 02/12] op-node: add 'import_time' field to block processing log --- op-node/rollup/engine/build_seal.go | 4 +++- op-node/rollup/engine/build_sealed.go | 2 ++ op-node/rollup/engine/payload_process.go | 13 ++++++++++++- op-node/rollup/engine/payload_success.go | 8 +++++++- op-node/rollup/sequencing/sequencer_chaos_test.go | 8 +++++++- 5 files changed, 31 insertions(+), 4 deletions(-) diff --git a/op-node/rollup/engine/build_seal.go b/op-node/rollup/engine/build_seal.go index 99a7e63c9c1..ea916bff3b7 100644 --- a/op-node/rollup/engine/build_seal.go +++ b/op-node/rollup/engine/build_seal.go @@ -44,6 +44,7 @@ func (ev PayloadSealExpiredErrorEvent) String() string { type BuildSealEvent struct { Info eth.PayloadInfo BuildStarted time.Time + BuildTime time.Duration // if payload should be promoted to safe (must also be pending safe, see DerivedFrom) Concluding bool // payload is promoted to pending-safe if non-zero @@ -112,7 +113,7 @@ 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, + 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), @@ -122,6 +123,7 @@ func (eq *EngDeriver) onBuildSeal(ev BuildSealEvent) { Concluding: ev.Concluding, DerivedFrom: ev.DerivedFrom, BuildStarted: ev.BuildStarted, + BuildTime: buildTime, Info: ev.Info, Envelope: envelope, Ref: ref, diff --git a/op-node/rollup/engine/build_sealed.go b/op-node/rollup/engine/build_sealed.go index 5ceff489ecc..25dbc74eb91 100644 --- a/op-node/rollup/engine/build_sealed.go +++ b/op-node/rollup/engine/build_sealed.go @@ -14,6 +14,7 @@ type BuildSealedEvent struct { // payload is promoted to pending-safe if non-zero DerivedFrom eth.L1BlockRef BuildStarted time.Time + BuildTime time.Duration Info eth.PayloadInfo Envelope *eth.ExecutionPayloadEnvelope @@ -33,6 +34,7 @@ func (eq *EngDeriver) onBuildSealed(ev BuildSealedEvent) { Envelope: ev.Envelope, Ref: ev.Ref, BuildStarted: ev.BuildStarted, + BuildTime: ev.BuildTime, }) } } diff --git a/op-node/rollup/engine/payload_process.go b/op-node/rollup/engine/payload_process.go index c6b1e542c6d..2f08de2685a 100644 --- a/op-node/rollup/engine/payload_process.go +++ b/op-node/rollup/engine/payload_process.go @@ -15,6 +15,7 @@ type PayloadProcessEvent struct { // payload is promoted to pending-safe if non-zero DerivedFrom eth.L1BlockRef BuildStarted time.Time + BuildTime time.Duration Envelope *eth.ExecutionPayloadEnvelope Ref eth.L2BlockRef @@ -28,6 +29,7 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) { ctx, cancel := context.WithTimeout(eq.ctx, payloadProcessTimeout) defer cancel() + startTime := time.Now() status, err := eq.ec.engine.NewPayload(ctx, ev.Envelope.ExecutionPayload, ev.Envelope.ParentBeaconBlockRoot) if err != nil { @@ -51,7 +53,16 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) { }) return case eth.ExecutionValid: - eq.emitter.Emit(PayloadSuccessEvent(ev)) + importTime := time.Since(startTime) + eq.emitter.Emit(PayloadSuccessEvent{ + Concluding: ev.Concluding, + DerivedFrom: ev.DerivedFrom, + BuildStarted: ev.BuildStarted, + BuildTime: ev.BuildTime, + ImportTime: importTime, + Envelope: ev.Envelope, + Ref: ev.Ref, + }) return default: eq.emitter.Emit(rollup.EngineTemporaryErrorEvent{ diff --git a/op-node/rollup/engine/payload_success.go b/op-node/rollup/engine/payload_success.go index 35a1e374dc0..b1c667dceb7 100644 --- a/op-node/rollup/engine/payload_success.go +++ b/op-node/rollup/engine/payload_success.go @@ -4,6 +4,7 @@ import ( "time" "github.com/ethereum-optimism/optimism/op-service/eth" + "github.com/ethereum/go-ethereum/common" ) type PayloadSuccessEvent struct { @@ -12,6 +13,8 @@ type PayloadSuccessEvent struct { // payload is promoted to pending-safe if non-zero DerivedFrom eth.L1BlockRef BuildStarted time.Time + BuildTime time.Duration + ImportTime time.Duration Envelope *eth.ExecutionPayloadEnvelope Ref eth.L2BlockRef @@ -39,7 +42,10 @@ func (eq *EngDeriver) onPayloadSuccess(ev PayloadSuccessEvent) { "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, - "elapsed", elapsed, "mgas", float64(payload.GasUsed)/1000000, + "build_time", common.PrettyDuration(ev.BuildTime), + "import_time", common.PrettyDuration(ev.ImportTime), + "total_time", common.PrettyDuration(elapsed), + "mgas", float64(payload.GasUsed)/1000000, "mgasps", float64(payload.GasUsed)*1000/float64(elapsed)) eq.emitter.Emit(TryUpdateEngineEvent{}) diff --git a/op-node/rollup/sequencing/sequencer_chaos_test.go b/op-node/rollup/sequencing/sequencer_chaos_test.go index d5000fbed33..93ba254c1b5 100644 --- a/op-node/rollup/sequencing/sequencer_chaos_test.go +++ b/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{}) } From 72b065456cca424b3f6cd5cd234f43d507c841bf Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Thu, 14 Nov 2024 10:53:21 -0500 Subject: [PATCH 03/12] op-node: make log message more descriptive --- op-node/rollup/engine/payload_success.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/op-node/rollup/engine/payload_success.go b/op-node/rollup/engine/payload_success.go index b1c667dceb7..893815afcfe 100644 --- a/op-node/rollup/engine/payload_success.go +++ b/op-node/rollup/engine/payload_success.go @@ -38,7 +38,7 @@ func (eq *EngDeriver) onPayloadSuccess(ev PayloadSuccessEvent) { elapsed := time.Since(ev.BuildStarted) payload := ev.Envelope.ExecutionPayload - eq.log.Info("Inserted block", "hash", payload.BlockHash, "number", uint64(payload.BlockNumber), + eq.log.Info("Inserted new L2 unsafe 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, From 29ee466691051d0bd3aaf21740009d7ff0900fb1 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Mon, 18 Nov 2024 10:33:46 -0500 Subject: [PATCH 04/12] op-node: log legacy codepath for InsertUnsafePayload --- op-node/rollup/engine/engine_controller.go | 14 ++++++++++++++ 1 file changed, 14 insertions(+) diff --git a/op-node/rollup/engine/engine_controller.go b/op-node/rollup/engine/engine_controller.go index b088e382f07..cbd8f657fa4 100644 --- a/op-node/rollup/engine/engine_controller.go +++ b/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 } From 61c13348bde5a8ecf99c469f0b4a894bbd4ca8b7 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Mon, 18 Nov 2024 10:39:30 -0500 Subject: [PATCH 05/12] op-node: include final ForkchoiceUpdate in block insertion time --- op-node/rollup/engine/events.go | 41 +++++++++++++++++++++++- op-node/rollup/engine/payload_process.go | 16 ++++----- op-node/rollup/engine/payload_success.go | 26 +++++---------- 3 files changed, 55 insertions(+), 28 deletions(-) diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index bb449956487..8b6b2f57caa 100644 --- a/op-node/rollup/engine/events.go +++ b/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) diff --git a/op-node/rollup/engine/payload_process.go b/op-node/rollup/engine/payload_process.go index 2f08de2685a..a3cd03939e1 100644 --- a/op-node/rollup/engine/payload_process.go +++ b/op-node/rollup/engine/payload_process.go @@ -29,7 +29,7 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) { ctx, cancel := context.WithTimeout(eq.ctx, payloadProcessTimeout) defer cancel() - startTime := time.Now() + insertStart := time.Now() status, err := eq.ec.engine.NewPayload(ctx, ev.Envelope.ExecutionPayload, ev.Envelope.ParentBeaconBlockRoot) if err != nil { @@ -53,15 +53,13 @@ func (eq *EngDeriver) onPayloadProcess(ev PayloadProcessEvent) { }) return case eth.ExecutionValid: - importTime := time.Since(startTime) eq.emitter.Emit(PayloadSuccessEvent{ - Concluding: ev.Concluding, - DerivedFrom: ev.DerivedFrom, - BuildStarted: ev.BuildStarted, - BuildTime: ev.BuildTime, - ImportTime: importTime, - Envelope: ev.Envelope, - Ref: ev.Ref, + Concluding: ev.Concluding, + DerivedFrom: ev.DerivedFrom, + BuildStarted: ev.BuildStarted, + InsertStarted: insertStart, + Envelope: ev.Envelope, + Ref: ev.Ref, }) return default: diff --git a/op-node/rollup/engine/payload_success.go b/op-node/rollup/engine/payload_success.go index 893815afcfe..17d8b0163b5 100644 --- a/op-node/rollup/engine/payload_success.go +++ b/op-node/rollup/engine/payload_success.go @@ -4,17 +4,15 @@ import ( "time" "github.com/ethereum-optimism/optimism/op-service/eth" - "github.com/ethereum/go-ethereum/common" ) 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 - BuildStarted time.Time - BuildTime time.Duration - ImportTime time.Duration + DerivedFrom eth.L1BlockRef + BuildStarted time.Time + InsertStarted time.Time Envelope *eth.ExecutionPayloadEnvelope Ref eth.L2BlockRef @@ -36,17 +34,9 @@ func (eq *EngDeriver) onPayloadSuccess(ev PayloadSuccessEvent) { }) } - elapsed := time.Since(ev.BuildStarted) - payload := ev.Envelope.ExecutionPayload - eq.log.Info("Inserted new L2 unsafe 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, - "build_time", common.PrettyDuration(ev.BuildTime), - "import_time", common.PrettyDuration(ev.ImportTime), - "total_time", common.PrettyDuration(elapsed), - "mgas", float64(payload.GasUsed)/1000000, - "mgasps", float64(payload.GasUsed)*1000/float64(elapsed)) - - eq.emitter.Emit(TryUpdateEngineEvent{}) + eq.emitter.Emit(TryUpdateEngineEvent{ + BuildStarted: ev.BuildStarted, + InsertStarted: ev.InsertStarted, + Envelope: ev.Envelope, + }) } From 020d4e31a9d7238aafed6c9c9b2b2702ba699146 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Mon, 18 Nov 2024 10:46:02 -0500 Subject: [PATCH 06/12] op-node: remove unused BuildTime field from events --- op-node/rollup/engine/build_seal.go | 2 -- op-node/rollup/engine/build_sealed.go | 2 -- op-node/rollup/engine/payload_process.go | 1 - 3 files changed, 5 deletions(-) diff --git a/op-node/rollup/engine/build_seal.go b/op-node/rollup/engine/build_seal.go index ea916bff3b7..50a05de8b26 100644 --- a/op-node/rollup/engine/build_seal.go +++ b/op-node/rollup/engine/build_seal.go @@ -44,7 +44,6 @@ func (ev PayloadSealExpiredErrorEvent) String() string { type BuildSealEvent struct { Info eth.PayloadInfo BuildStarted time.Time - BuildTime time.Duration // if payload should be promoted to safe (must also be pending safe, see DerivedFrom) Concluding bool // payload is promoted to pending-safe if non-zero @@ -123,7 +122,6 @@ func (eq *EngDeriver) onBuildSeal(ev BuildSealEvent) { Concluding: ev.Concluding, DerivedFrom: ev.DerivedFrom, BuildStarted: ev.BuildStarted, - BuildTime: buildTime, Info: ev.Info, Envelope: envelope, Ref: ref, diff --git a/op-node/rollup/engine/build_sealed.go b/op-node/rollup/engine/build_sealed.go index 25dbc74eb91..5ceff489ecc 100644 --- a/op-node/rollup/engine/build_sealed.go +++ b/op-node/rollup/engine/build_sealed.go @@ -14,7 +14,6 @@ type BuildSealedEvent struct { // payload is promoted to pending-safe if non-zero DerivedFrom eth.L1BlockRef BuildStarted time.Time - BuildTime time.Duration Info eth.PayloadInfo Envelope *eth.ExecutionPayloadEnvelope @@ -34,7 +33,6 @@ func (eq *EngDeriver) onBuildSealed(ev BuildSealedEvent) { Envelope: ev.Envelope, Ref: ev.Ref, BuildStarted: ev.BuildStarted, - BuildTime: ev.BuildTime, }) } } diff --git a/op-node/rollup/engine/payload_process.go b/op-node/rollup/engine/payload_process.go index a3cd03939e1..272fce3febc 100644 --- a/op-node/rollup/engine/payload_process.go +++ b/op-node/rollup/engine/payload_process.go @@ -15,7 +15,6 @@ type PayloadProcessEvent struct { // payload is promoted to pending-safe if non-zero DerivedFrom eth.L1BlockRef BuildStarted time.Time - BuildTime time.Duration Envelope *eth.ExecutionPayloadEnvelope Ref eth.L2BlockRef From ddc086d3f90736679627f523f2222f407f96e1fd Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Mon, 18 Nov 2024 15:29:07 -0500 Subject: [PATCH 07/12] op-node: encapsulate log logic in TryUpdateEngineEvent methods --- op-node/rollup/engine/events.go | 78 +++++++++++++++++++-------------- 1 file changed, 44 insertions(+), 34 deletions(-) diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index 8b6b2f57caa..698231ccf3e 100644 --- a/op-node/rollup/engine/events.go +++ b/op-node/rollup/engine/events.go @@ -214,6 +214,47 @@ 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 { + if ev.Envelope != nil { + return true + } + return false +} + +// 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() + logValues := make([]interface{}, 0) + payload := ev.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 !ev.BuildStarted.IsZero() { + totalTime = time.Since(ev.BuildStarted) + logValues = append(logValues, "build_time", common.PrettyDuration(ev.InsertStarted.Sub(ev.BuildStarted))) + logValues = append(logValues, "insert_time", common.PrettyDuration(fcuFinish.Sub(ev.InsertStarted))) + } else if !ev.InsertStarted.IsZero() { + totalTime = time.Since(ev.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)) + + return logValues +} + type ForceEngineResetEvent struct { Unsafe, Safe, Finalized eth.L2BlockRef } @@ -327,40 +368,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.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...) - } - + } 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) From 4952ff380587d91144e5b8d2c41833770ddf25ce Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Mon, 18 Nov 2024 15:31:25 -0500 Subject: [PATCH 08/12] op-node: linter fix --- op-node/rollup/engine/events.go | 5 +---- 1 file changed, 1 insertion(+), 4 deletions(-) diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index 698231ccf3e..034387a6fa8 100644 --- a/op-node/rollup/engine/events.go +++ b/op-node/rollup/engine/events.go @@ -217,10 +217,7 @@ func (ev TryUpdateEngineEvent) String() string { // Checks for the existence of the Envelope field, which is only // added by the PayloadSuccessEvent func (ev TryUpdateEngineEvent) triggeredByPayloadSuccess() bool { - if ev.Envelope != nil { - return true - } - return false + return ev.Envelope != nil } // Returns key/value pairs that can be logged and are useful for plotting From 026614d0f5b2c286a0ba552cbdfb16ae72dd6cca Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Tue, 19 Nov 2024 11:28:46 -0500 Subject: [PATCH 09/12] op-node: add comment and adjust sync log wording --- op-node/rollup/engine/engine_controller.go | 2 +- op-node/rollup/engine/events.go | 2 ++ 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/op-node/rollup/engine/engine_controller.go b/op-node/rollup/engine/engine_controller.go index cbd8f657fa4..907238e84a9 100644 --- a/op-node/rollup/engine/engine_controller.go +++ b/op-node/rollup/engine/engine_controller.go @@ -402,7 +402,7 @@ func (e *EngineController) InsertUnsafePayload(ctx context.Context, envelope *et } totalTime := fcu2Finish.Sub(newPayloadStart) - e.log.Info("Inserted new L2 unsafe block (legacy)", + 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)), diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index 034387a6fa8..7c497cd504d 100644 --- a/op-node/rollup/engine/events.go +++ b/op-node/rollup/engine/events.go @@ -205,6 +205,8 @@ func (ev TryBackupUnsafeReorgEvent) String() string { } 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 From 82437defea131b15d593e22921d6e21e2be8af89 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Tue, 19 Nov 2024 14:59:26 -0500 Subject: [PATCH 10/12] op-node: fix BlockHash, BlockNumber in log --- op-node/rollup/engine/events.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index 7c497cd504d..15b65db43bd 100644 --- a/op-node/rollup/engine/events.go +++ b/op-node/rollup/engine/events.go @@ -229,8 +229,8 @@ func (ev TryUpdateEngineEvent) getBlockProcessingMetrics() []interface{} { logValues := make([]interface{}, 0) payload := ev.Envelope.ExecutionPayload - logValues = append(logValues, "hash", uint64(payload.BlockNumber)) - logValues = append(logValues, "number", payload.BlockHash) + logValues = append(logValues, "hash", payload.BlockHash) + logValues = append(logValues, "number", uint64(payload.BlockNumber)) logValues = append(logValues, "state_root", payload.StateRoot) logValues = append(logValues, "timestamp", uint64(payload.Timestamp)) logValues = append(logValues, "parent", payload.ParentHash) From 30669df98db89656bad93a4aeda6c14eef6e1c9b Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Tue, 19 Nov 2024 15:23:35 -0500 Subject: [PATCH 11/12] op-node: seq add BuildStarted to PayloadProcessEvent --- op-node/rollup/sequencing/sequencer.go | 9 +++++---- 1 file changed, 5 insertions(+), 4 deletions(-) diff --git a/op-node/rollup/sequencing/sequencer.go b/op-node/rollup/sequencing/sequencer.go index b6605d601fa..65aec431fc5 100644 --- a/op-node/rollup/sequencing/sequencer.go +++ b/op-node/rollup/sequencing/sequencer.go @@ -281,10 +281,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 From b6cf3133399639aab31d06eb25a2e97467af74e2 Mon Sep 17 00:00:00 2001 From: Samuel Stokes Date: Tue, 19 Nov 2024 15:55:09 -0500 Subject: [PATCH 12/12] op-node: refactor getBlockProcessingMetrics, protect against divide-by-zero --- op-node/rollup/engine/events.go | 43 +++++++++++++++++++++------------ 1 file changed, 27 insertions(+), 16 deletions(-) diff --git a/op-node/rollup/engine/events.go b/op-node/rollup/engine/events.go index 15b65db43bd..24f259a561d 100644 --- a/op-node/rollup/engine/events.go +++ b/op-node/rollup/engine/events.go @@ -226,30 +226,41 @@ func (ev TryUpdateEngineEvent) triggeredByPayloadSuccess() bool { // block build/insert time as a way to measure performance. func (ev TryUpdateEngineEvent) getBlockProcessingMetrics() []interface{} { fcuFinish := time.Now() - logValues := make([]interface{}, 0) payload := ev.Envelope.ExecutionPayload - logValues = append(logValues, "hash", payload.BlockHash) - logValues = append(logValues, "number", uint64(payload.BlockNumber)) - 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)) + 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 = time.Since(ev.BuildStarted) - logValues = append(logValues, "build_time", common.PrettyDuration(ev.InsertStarted.Sub(ev.BuildStarted))) - logValues = append(logValues, "insert_time", common.PrettyDuration(fcuFinish.Sub(ev.InsertStarted))) + 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 = time.Since(ev.InsertStarted) + 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)) - logValues = append(logValues, "mgas", float64(payload.GasUsed)/1000000) - logValues = append(logValues, "mgasps", float64(payload.GasUsed)*1000/float64(totalTime)) + logValues = append(logValues, + "total_time", common.PrettyDuration(totalTime), + "mgas", float64(payload.GasUsed)/1000000, + "mgasps", mgasps, + ) return logValues }