Skip to content

fix(block): fix blocktime timer usage#3137

Merged
chatton merged 2 commits intomainfrom
cian/fix-block-time-timer-usage
Mar 5, 2026
Merged

fix(block): fix blocktime timer usage#3137
chatton merged 2 commits intomainfrom
cian/fix-block-time-timer-usage

Conversation

@chatton
Copy link
Contributor

@chatton chatton commented Mar 5, 2026

Overview

While benchmarking, I have a situation in which we have a 250ms block time, ProduceBlock took ~220ms

however the average interval I was seeing was ~470ms

In the call blockTimer.Reset, it is waiting an additional block_time ms on top of the time it took to actually produce the block.

This PR subtracts the time it took to produce the block from the value passed to the reset call so it is included in the blocktime.

Summary by CodeRabbit

  • Bug Fixes

    • Block production timer now subtracts time spent producing a block, preserving the configured cadence and yielding more accurate intervals.
  • Tests

    • Added tests that simulate block production time and verify intervals between block starts match the intended schedule.
  • Documentation

    • Updated changelog to record the timing fix and its effect on block cadence.

@coderabbitai
Copy link
Contributor

coderabbitai bot commented Mar 5, 2026

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info
⚙️ Run configuration

Configuration used: defaults

Review profile: CHILL

Plan: Pro

Run ID: 0d05eb9f-bee5-4df6-a362-447b7f16f746

📥 Commits

Reviewing files that changed from the base of the PR and between 6280d1e and 45db47b.

📒 Files selected for processing (1)
  • CHANGELOG.md
✅ Files skipped from review due to trivial changes (1)
  • CHANGELOG.md

📝 Walkthrough

Walkthrough

The executor's block timer now measures the time spent producing a block and subtracts that elapsed time from the configured block duration when resetting the timer. Tests and test helpers were added to validate that block intervals reflect production time.

Changes

Cohort / File(s) Summary
Block Execution Timer Logic
block/internal/executing/executor.go
Capture start time before ProduceBlock, compute elapsed after production, and reset the block timer to blockTime - elapsed (respecting lazy mode and existing flow).
Test Infrastructure & Validation
block/internal/executing/executor_logic_test.go
Added stubBlockProducer to simulate production latency, switched to dssync.MutexWrap(...), and added TestExecutionLoop_BlockInterval to assert intervals account for production time.
Changelog
CHANGELOG.md
Documented the fix: timer now subtracts elapsed execution time to preserve configured cadence.

Sequence Diagram(s)

sequenceDiagram
    participant Executor
    participant BlockProducer
    participant Timer
    Executor->>Timer: wait for next tick
    Timer-->>Executor: tick
    Executor->>Executor: record startTime
    Executor->>BlockProducer: ProduceBlock(ctx)
    BlockProducer-->>Executor: block produced
    Executor->>Executor: elapsed = now - startTime
    Executor->>Timer: reset(duration = blockTime - elapsed)
Loading

Estimated code review effort

🎯 3 (Moderate) | ⏱️ ~22 minutes

Suggested reviewers

  • julienrbrt

Poem

🐰 I hopped to the timer and gave it a tweak,

I counted the ticks while I built each block sleek,
No wasted seconds, the rhythm is true,
We sleep only what remains — hop, cadence, review! 🎩✨

🚥 Pre-merge checks | ✅ 2 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 33.33% which is insufficient. The required threshold is 80.00%. Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (2 passed)
Check name Status Explanation
Title check ✅ Passed The title accurately summarizes the main change: fixing the blocktime timer to correctly account for elapsed block production time.
Description check ✅ Passed The description provides clear context about the bug (250ms block time but ~470ms observed interval), explains the root cause (production time double-counted), and describes the fix (subtracting elapsed time from timer reset).

✏️ Tip: You can configure your own custom pre-merge checks in the settings.

✨ Finishing Touches
🧪 Generate unit tests (beta)
  • Create PR with unit tests
  • Post copyable unit tests in a comment
  • Commit unit tests in branch cian/fix-block-time-timer-usage

Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands and usage tips.

@chatton chatton marked this pull request as ready for review March 5, 2026 08:58
@github-actions
Copy link
Contributor

github-actions bot commented Mar 5, 2026

The latest Buf updates on your PR. Results from workflow CI / buf-check (pull_request).

BuildFormatLintBreakingUpdated (UTC)
✅ passed⏩ skipped✅ passed✅ passedMar 5, 2026, 9:06 AM

@claude
Copy link
Contributor

claude bot commented Mar 5, 2026

Claude finished @chatton's task in 1m 18s —— View job


Code Review

  • Read changed files
  • Analyze code quality and correctness
  • Check tests
  • Post review feedback

The fix is correct and well-targeted. The core change in executionLoop properly accounts for block production time when resetting the timer. Here are my observations:

Correctness

The fix in executor.go:418-429 is sound:

start := time.Now()
if err := e.blockProducer.ProduceBlock(e.ctx); err != nil {
    e.logger.Error().Err(err).Msg("failed to produce block")
}
// ...
elapsed := time.Since(start)
remaining := e.config.Node.BlockTime.Duration - elapsed
if remaining <= 0 {
    remaining = 0
}
blockTimer.Reset(remaining)
  • Elapsed time is subtracted correctly, even on error paths (we still spent time attempting production).
  • Clamping to 0 avoids negative durations.

Minor Issues

1. Lazy mode path is inconsistentblock/internal/executing/executor.go:433-437

The lazyTimerCh case still resets to the full LazyBlockInterval.Duration without accounting for execution time. If lazy mode blocks are expected to have accurate intervals too, this should be addressed consistently. If the semantics intentionally differ ("fire again after a full idle period"), a comment would clarify the intent.

2. Missing edge case test — The new TestExecutionLoop_BlockInterval test only covers the normal case where execution takes less than blockTime. The remaining <= 0 branch (execution time ≥ block time) is not tested, meaning that code path has 0 coverage (which aligns with the codecov report showing 2 missing lines). A test with executionTime >= blockTime would cover this and verify the timer fires immediately without blocking. Fix this →

3. Behavior when execution consistently exceeds block time — When remaining = 0, the timer fires immediately, meaning if block production is always slower than blockTime, the node will produce blocks back-to-back with no pause. This may be the desired "catch up" behavior, but a short comment clarifying this would improve readability:

if remaining <= 0 {
    remaining = 0 // block production exceeded target; fire immediately to catch up
}

Test Quality

The stubBlockProducer is well-implemented:

  • Mutex protection on callTimes is correct.
  • Uses testing/synctest for fake-time determinism — the interval assertions are exact because time.Now() advances by precise amounts in fake time.
  • defer timer.Stop() in ProduceBlock prevents goroutine/timer leaks.
  • Context cancellation is respected.

Performance Benchmarks

The benchmark regressions (EVM Contract Roundtrip: 1.68x allocs/op, SpamoorSmoke: ~3x latency) look unrelated to this change — they affect the execution layer, not the timer logic. These are likely environmental noise or pre-existing flakiness rather than a regression introduced here.

Summary

The fix is correct and addresses a real production issue. The two main improvements worth considering are: (1) covering the remaining <= 0 branch in tests, and (2) clarifying the lazy mode path. Neither is a blocker. This is a clean, focused bug fix with good test coverage for the happy path.

@codecov
Copy link

codecov bot commented Mar 5, 2026

Codecov Report

❌ Patch coverage is 66.66667% with 2 lines in your changes missing coverage. Please review.
✅ Project coverage is 61.00%. Comparing base (5a07bc3) to head (45db47b).
⚠️ Report is 2 commits behind head on main.

Files with missing lines Patch % Lines
block/internal/executing/executor.go 66.66% 1 Missing and 1 partial ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #3137      +/-   ##
==========================================
+ Coverage   60.82%   61.00%   +0.17%     
==========================================
  Files         113      113              
  Lines       11695    11700       +5     
==========================================
+ Hits         7114     7137      +23     
+ Misses       3777     3753      -24     
- Partials      804      810       +6     
Flag Coverage Δ
combined 61.00% <66.66%> (+0.17%) ⬆️

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

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

Copy link
Contributor

@github-actions github-actions bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'EVM Contract Roundtrip'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 1.50.

Benchmark suite Current: 45db47b Previous: 5a07bc3 Ratio
BenchmarkEvmContractRoundtrip - allocs/op 183590 allocs/op 112319 allocs/op 1.63

This comment was automatically generated by workflow using github-action-benchmark.

Copy link
Contributor

@github-actions github-actions bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Performance Alert ⚠️

Possible performance regression was detected for benchmark 'Spamoor Trace Benchmarks'.
Benchmark result of this commit is worse than the previous benchmark result exceeding threshold 1.50.

Benchmark suite Current: 45db47b Previous: 5a07bc3 Ratio
SpamoorSmoke - Executor.GetTxs (avg) 9104 us 993 us 9.17
SpamoorSmoke - TxPool.GetTxs (avg) 9017 us 977.75 us 9.22

This comment was automatically generated by workflow using github-action-benchmark.

@julienrbrt julienrbrt changed the title fix: fix blocktime timer usage fix(block): fix blocktime timer usage Mar 5, 2026
Copy link
Member

@julienrbrt julienrbrt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can we add a changelog entry?

@chatton chatton mentioned this pull request Mar 5, 2026
9 tasks
@chatton chatton added this pull request to the merge queue Mar 5, 2026
Merged via the queue into main with commit 6ed140a Mar 5, 2026
32 of 34 checks passed
@chatton chatton deleted the cian/fix-block-time-timer-usage branch March 5, 2026 09:43
alpe added a commit that referenced this pull request Mar 9, 2026
* main:
  chore: minor deduplication (#3139)
  refactor(store,cache)!: optimize cache restore as O(1) (#3134)
  ci: remove spamoor results from benchmark results per PR (#3138)
  build(deps): Bump rollup from 4.22.4 to 4.59.0 in /docs in the npm_and_yarn group across 1 directory (#3136)
  fix(block): fix blocktime timer usage (#3137)
  build(deps): bump core v1.0.0 (#3135)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants