Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

op-batcher: improve computeSyncActions() logging #14563

Merged
merged 3 commits into from
Feb 27, 2025

Conversation

geoknee
Copy link
Contributor

@geoknee geoknee commented Feb 27, 2025

Test output covers the various cases:

Running tool: /opt/homebrew/bin/go test -timeout 30s -run ^TestBatchSubmitter_computeSyncActions$ github.com/ethereum-optimism/optimism/op-batcher/batcher -v

=== RUN   TestBatchSubmitter_computeSyncActions
=== RUN   TestBatchSubmitter_computeSyncActions/empty_sync_status
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:61:         WARN [02-27|17:49:03.385] empty sync status                        newSyncStatus="SyncStatus{HeadL1: 0, CurrentL1: 0, LocalSafeL2: 0, UnsafeL2: 0}"
=== RUN   TestBatchSubmitter_computeSyncActions/current_l1_reversed
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:67:         WARN [02-27|17:49:03.385] sequencer currentL1 reversed             newSyncStatus="SyncStatus{HeadL1: 2, CurrentL1: 1, LocalSafeL2: 0, UnsafeL2: 0}" prevCurrentL1=000000..000000:2
=== RUN   TestBatchSubmitter_computeSyncActions/gap_between_safe_chain_and_state
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:100:        WARN [02-27|17:49:03.385] next safe block is below oldest block in state newSyncStatus="SyncStatus{HeadL1: 6, CurrentL1: 1, LocalSafeL2: 100, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: 000000..000000:1, blocksToLoad: [101, 109]}" oldestBlockInStateNum=102
=== RUN   TestBatchSubmitter_computeSyncActions/unexpectedly_good_progress
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:116:        WARN [02-27|17:49:03.385] safe head above newest block in state, clearing channel manager state newSyncStatus="SyncStatus{HeadL1: 6, CurrentL1: 2, LocalSafeL2: 104, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: 000000..000000:1, blocksToLoad: [105, 109]}" newestBlockInState=e9b71a..2b29ec:103
=== RUN   TestBatchSubmitter_computeSyncActions/safe_chain_reorg
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:124:        WARN [02-27|17:49:03.385] safe chain reorg, clearing channel manager state newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 103, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: 000000..000000:1, blocksToLoad: [104, 109]}" existingBlock=e9b71a..2b29ec:103
=== RUN   TestBatchSubmitter_computeSyncActions/failed_to_make_expected_progress
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:140:        WARN [02-27|17:49:03.385] sequencer did not make expected progress newSyncStatus="SyncStatus{HeadL1: 3, CurrentL1: 2, LocalSafeL2: 101, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: 000000..000000:1, blocksToLoad: [102, 109]}" existingBlock=e9b71a..2b29ec:103
=== RUN   TestBatchSubmitter_computeSyncActions/failed_to_make_expected_progress_(unsafe=safe)
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:140:        WARN [02-27|17:49:03.385] sequencer did not make expected progress newSyncStatus="SyncStatus{HeadL1: 3, CurrentL1: 2, LocalSafeL2: 101, UnsafeL2: 101}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: 000000..000000:1, blocksToLoad: nil}" existingBlock=e9b71a..2b29ec:103
=== RUN   TestBatchSubmitter_computeSyncActions/no_progress
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:168:        DEBUG[02-27|17:49:03.385] computed sync actions                    newSyncStatus="SyncStatus{HeadL1: 4, CurrentL1: 1, LocalSafeL2: 100, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: nil, blocksToLoad: [104, 109]}"
=== RUN   TestBatchSubmitter_computeSyncActions/no_blocks
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:83:         INFO [02-27|17:49:03.385] no blocks in state                       newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 103, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: nil, blocksToLoad: [104, 109]}"
=== RUN   TestBatchSubmitter_computeSyncActions/happy_path
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:168:        DEBUG[02-27|17:49:03.385] computed sync actions                    newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 103, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 3, channelsToPrune: 1, clearState: nil, blocksToLoad: [104, 109]}"
=== RUN   TestBatchSubmitter_computeSyncActions/happy_path_+_multiple_channels
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:168:        DEBUG[02-27|17:49:03.385] computed sync actions                    newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 103, UnsafeL2: 109}" syncActions="SyncActions{blocksToPrune: 3, channelsToPrune: 1, clearState: nil, blocksToLoad: [105, 109]}"
=== RUN   TestBatchSubmitter_computeSyncActions/no_progress_+_unsafe=safe
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:83:         INFO [02-27|17:49:03.385] no blocks in state                       newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 100, UnsafeL2: 100}" syncActions="SyncActions{blocksToPrune: 0, channelsToPrune: 0, clearState: nil, blocksToLoad: nil}"
=== RUN   TestBatchSubmitter_computeSyncActions/no_progress_+_unsafe=safe_+_blocks_in_state
    /Users/georgeknee/code/ethereum-optimism/optimism/op-batcher/batcher/sync_actions.go:168:        DEBUG[02-27|17:49:03.385] computed sync actions                    newSyncStatus="SyncStatus{HeadL1: 5, CurrentL1: 2, LocalSafeL2: 101, UnsafeL2: 101}" syncActions="SyncActions{blocksToPrune: 1, channelsToPrune: 0, clearState: nil, blocksToLoad: nil}"
--- PASS: TestBatchSubmitter_computeSyncActions (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/empty_sync_status (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/current_l1_reversed (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/gap_between_safe_chain_and_state (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/unexpectedly_good_progress (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/safe_chain_reorg (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/failed_to_make_expected_progress (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/failed_to_make_expected_progress_(unsafe=safe) (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/no_progress (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/no_blocks (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/happy_path (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/happy_path_+_multiple_channels (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/no_progress_+_unsafe=safe (0.00s)
    --- PASS: TestBatchSubmitter_computeSyncActions/no_progress_+_unsafe=safe_+_blocks_in_state (0.00s)
PASS
ok      github.com/ethereum-optimism/optimism/op-batcher/batcher        0.417s

@geoknee geoknee requested review from a team as code owners February 27, 2025 17:52
@geoknee geoknee requested a review from protolambda February 27, 2025 17:52
@geoknee geoknee added the A-op-batcher Area: op-batcher label Feb 27, 2025
@geoknee geoknee requested a review from sebastianst February 27, 2025 17:55
Copy link

codecov bot commented Feb 27, 2025

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 42.06%. Comparing base (ade9ad0) to head (92543b5).
Report is 2 commits behind head on develop.

Additional details and impacted files
@@             Coverage Diff             @@
##           develop   #14563      +/-   ##
===========================================
- Coverage    46.54%   42.06%   -4.49%     
===========================================
  Files         1036      865     -171     
  Lines        88779    78830    -9949     
===========================================
- Hits         41323    33156    -8167     
+ Misses       44379    42788    -1591     
+ Partials      3077     2886     -191     
Flag Coverage Δ
cannon-go-tests-32 ?
cannon-go-tests-64 ?
contracts-bedrock-tests ?

Flags with carried forward coverage won't be shown. Click here to find out more.

Files with missing lines Coverage Δ
op-batcher/batcher/sync_actions.go 100.00% <100.00%> (+73.19%) ⬆️

... and 180 files with indirect coverage changes

@geoknee geoknee enabled auto-merge February 27, 2025 18:26
@geoknee geoknee added this pull request to the merge queue Feb 27, 2025
Merged via the queue into develop with commit e4297b4 Feb 27, 2025
46 checks passed
@geoknee geoknee deleted the gk/batcher-next-safe-below branch February 27, 2025 18:37
karlb pushed a commit to celo-org/optimism that referenced this pull request Mar 4, 2025
…#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger
karlb pushed a commit to celo-org/optimism that referenced this pull request Mar 4, 2025
…#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger
karlb pushed a commit to celo-org/optimism that referenced this pull request Mar 4, 2025
…#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger
karlb pushed a commit to celo-org/optimism that referenced this pull request Mar 5, 2025
…#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger
palango pushed a commit to celo-org/optimism that referenced this pull request Mar 6, 2025
* op-batcher: prevent `SpanChannelOut` RLP bytes overflowing `MaxRLPBytesPerChannel` (ethereum-optimism#14310)

* fix op-batcher pack over MaxRLPBytesChannel

* add test cases from different CompressionAlgo

* add fresh compression logic and corresponding comments

* refactor: enhance MaxRLPBytesPerChannel test

* refactor: rename variable and add required messages

* op-batcher: use local-safe to reduce lag during interop sync (ethereum-optimism#14265)

* op-batcher: remove `ThrottleInterval` and split block loading and batch publishing into separate goroutines (ethereum-optimism#14244)

* op-batcher: overhaul throttling, reading and writing loops

* no longer evaluate throttling conditions on a ticker
* break main loop into "reading" and "writing"
* reading loop signals to throttling and writing when ALL blocks are loaded (this could be done in a more fine grained way, even when each block is loaded)
* these run concurrently

* improvements

* readloop unblocks writing loop once, and then writing loop goes forever (pausing when it runs out of data)

tests pass but timeout due to bad shutdown

* rename to prevent shadowing

* allow for receipt handling when receipt and err are both nil

* split shutdownCtx into producers and consumers

* throttling loop ranges over a channel, does not take a context

* processReceiptsLoop ranges over a channel, does not take a context

* unify wait groups

* unify contexts

* writeLoop uses a ticker instead of a sleep

* WIP: add throughput test for batcher

* make txQueue local, not global state

* reduce diff

* reduce diff further

* make pendingBytesUpdated a local, not global

* read and write loop communicate with a channel

no more ticker required

* rename

* rename

* abstract promptLoop

* rename

* update readme

* add diagram to readme

* remove test

I'm not sure it is adding any value. May return to it in future

* sendToThrottlingLoop uses mutex

* harmonize "*Loop returning" logs

* tidy

* remove TODO

* rip out ThrottleInterval config var

* add activeSequencerChanged channel and wire it up to onActiveSequencerChanged hook in active rollup provider

* set callback at runtime, not in constructor

* reinstate startup order

* tidy

* remove dead code

* remove unintentional change

* rename readLoop to blockLoadingLoop and writeLoop to publishingLoop

* improve diagram

* replace ThrottleInterval with ThrottleThreshold as enabling var

* remove onActiveProviderChanged arg from constructors

* protect callback invocation with nullity check

* lint

* Apply suggestions from code review

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* remove ThrottelInterval from flags

* docs: mention active sequencer signal

* only attach callback if throttling is enabled

* increase buffer of activeSequencerChanged

means that we buffer a single event if the throttlingLoop is busy, even when using a try-send

* add buffer to pendingBytesUpdated

see previous commit

* reduce indentation

* remove dangling ref

* pass killCtx to publishingLoop and avoid accessing this context globally

* remove continue and always signal publishing loop

* remove unecessary mutex wrangle

* replace signalPublishingLoop method with trySignal fn

* extend TestRollupProvider_FailoverOnInactiveSequencer to cover callback fn

* use retryTimer in throttlingLoop

if RPC calls fail, they will be retried after retryInterval (or before, if another event triggers updateParams)

* op-batcher: improve active-seq-changed signalling setup

* remove unused state var

* rename blocksLoaded channel to publishSignal channel

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: add `TestBatchSubmitter_sendTx_FloorDataGas` and patch `driver.sendTx` (ethereum-optimism#14517)

* op-batcher: add TestBatchSubmitter_sendTx_FloorDataGas

* op-batcher: use floorDataGas for transactions if greater than intrinsicGas

* Update op-batcher/batcher/driver.go

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* log error instead of ignoring

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: always `updateCursorAndMetrics` when returning from `processBlocks()` (ethereum-optimism#14520)

* op-batcher: always updateCursorAndMetrics when returning from processBlocks()

* Update op-batcher/batcher/channel_manager.go

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: remove `ChannelManager.CheckExpectedProgress()` and add channel timeout log (ethereum-optimism#14553)

* op-batcher: remove ChannelManager.CheckExpectedProgress

* op-batcher: add warning log when a channel times out on chain

* op-batcher: correctly track block metrics in `handleChannelInvalidated()` (ethereum-optimism#14561)

* op-batcher: correctly track block metrics in handleChannelInvalidated

Includes test which fails without the fix.

* op-batcher: log out channels which are dropped during handleChannelInvalidated()

* change to warn log for dropped channels

* op-batcher: improve `computeSyncActions()` logging (ethereum-optimism#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger

* op-batcher: introduce `PREFER_LOCAL_SAFE_L2` config var (ethereum-optimism#14587)

* op-batcher: introduce PREFER_LOCAL_SAFE_L2 config var

* lint

* Apply suggestions from code review

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* lint

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* batcher: Wait for DA write before shutdown

---------

Co-authored-by: olga yang <ya1994ng@gmail.com>
Co-authored-by: protolambda <proto@protolambda.com>
Co-authored-by: George Knee <georgeknee@googlemail.com>
Co-authored-by: Sebastian Stammler <seb@oplabs.co>
QuentinI pushed a commit to EspressoSystems/optimism-espresso-integration that referenced this pull request Mar 7, 2025
* op-batcher: prevent `SpanChannelOut` RLP bytes overflowing `MaxRLPBytesPerChannel` (ethereum-optimism#14310)

* fix op-batcher pack over MaxRLPBytesChannel

* add test cases from different CompressionAlgo

* add fresh compression logic and corresponding comments

* refactor: enhance MaxRLPBytesPerChannel test

* refactor: rename variable and add required messages

* op-batcher: use local-safe to reduce lag during interop sync (ethereum-optimism#14265)

* op-batcher: remove `ThrottleInterval` and split block loading and batch publishing into separate goroutines (ethereum-optimism#14244)

* op-batcher: overhaul throttling, reading and writing loops

* no longer evaluate throttling conditions on a ticker
* break main loop into "reading" and "writing"
* reading loop signals to throttling and writing when ALL blocks are loaded (this could be done in a more fine grained way, even when each block is loaded)
* these run concurrently

* improvements

* readloop unblocks writing loop once, and then writing loop goes forever (pausing when it runs out of data)

tests pass but timeout due to bad shutdown

* rename to prevent shadowing

* allow for receipt handling when receipt and err are both nil

* split shutdownCtx into producers and consumers

* throttling loop ranges over a channel, does not take a context

* processReceiptsLoop ranges over a channel, does not take a context

* unify wait groups

* unify contexts

* writeLoop uses a ticker instead of a sleep

* WIP: add throughput test for batcher

* make txQueue local, not global state

* reduce diff

* reduce diff further

* make pendingBytesUpdated a local, not global

* read and write loop communicate with a channel

no more ticker required

* rename

* rename

* abstract promptLoop

* rename

* update readme

* add diagram to readme

* remove test

I'm not sure it is adding any value. May return to it in future

* sendToThrottlingLoop uses mutex

* harmonize "*Loop returning" logs

* tidy

* remove TODO

* rip out ThrottleInterval config var

* add activeSequencerChanged channel and wire it up to onActiveSequencerChanged hook in active rollup provider

* set callback at runtime, not in constructor

* reinstate startup order

* tidy

* remove dead code

* remove unintentional change

* rename readLoop to blockLoadingLoop and writeLoop to publishingLoop

* improve diagram

* replace ThrottleInterval with ThrottleThreshold as enabling var

* remove onActiveProviderChanged arg from constructors

* protect callback invocation with nullity check

* lint

* Apply suggestions from code review

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* remove ThrottelInterval from flags

* docs: mention active sequencer signal

* only attach callback if throttling is enabled

* increase buffer of activeSequencerChanged

means that we buffer a single event if the throttlingLoop is busy, even when using a try-send

* add buffer to pendingBytesUpdated

see previous commit

* reduce indentation

* remove dangling ref

* pass killCtx to publishingLoop and avoid accessing this context globally

* remove continue and always signal publishing loop

* remove unecessary mutex wrangle

* replace signalPublishingLoop method with trySignal fn

* extend TestRollupProvider_FailoverOnInactiveSequencer to cover callback fn

* use retryTimer in throttlingLoop

if RPC calls fail, they will be retried after retryInterval (or before, if another event triggers updateParams)

* op-batcher: improve active-seq-changed signalling setup

* remove unused state var

* rename blocksLoaded channel to publishSignal channel

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: add `TestBatchSubmitter_sendTx_FloorDataGas` and patch `driver.sendTx` (ethereum-optimism#14517)

* op-batcher: add TestBatchSubmitter_sendTx_FloorDataGas

* op-batcher: use floorDataGas for transactions if greater than intrinsicGas

* Update op-batcher/batcher/driver.go

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* log error instead of ignoring

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: always `updateCursorAndMetrics` when returning from `processBlocks()` (ethereum-optimism#14520)

* op-batcher: always updateCursorAndMetrics when returning from processBlocks()

* Update op-batcher/batcher/channel_manager.go

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* op-batcher: remove `ChannelManager.CheckExpectedProgress()` and add channel timeout log (ethereum-optimism#14553)

* op-batcher: remove ChannelManager.CheckExpectedProgress

* op-batcher: add warning log when a channel times out on chain

* op-batcher: correctly track block metrics in `handleChannelInvalidated()` (ethereum-optimism#14561)

* op-batcher: correctly track block metrics in handleChannelInvalidated

Includes test which fails without the fix.

* op-batcher: log out channels which are dropped during handleChannelInvalidated()

* change to warn log for dropped channels

* op-batcher: improve `computeSyncActions()` logging (ethereum-optimism#14563)

* improve computeSyncActions logging

* fixup test and make sure all cases run (!)

* use more friendly format for structured logger

* op-batcher: introduce `PREFER_LOCAL_SAFE_L2` config var (ethereum-optimism#14587)

* op-batcher: introduce PREFER_LOCAL_SAFE_L2 config var

* lint

* Apply suggestions from code review

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* lint

---------

Co-authored-by: Sebastian Stammler <seb@oplabs.co>

* batcher: Wait for DA write before shutdown

---------

Co-authored-by: olga yang <ya1994ng@gmail.com>
Co-authored-by: protolambda <proto@protolambda.com>
Co-authored-by: George Knee <georgeknee@googlemail.com>
Co-authored-by: Sebastian Stammler <seb@oplabs.co>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-op-batcher Area: op-batcher
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants