tests: log phase boundaries in the cleanup tests to diagnose the CI hang (#516)#553
tests: log phase boundaries in the cleanup tests to diagnose the CI hang (#516)#553eduralph wants to merge 1 commit into
Conversation
failpoint_tests::txn_cleanup_2pc_locks intermittently stalls in CI until nextest's 600s cap kills it (tikv#516); txn_cleanup_async_commit_locks has hit the same thing. A killed test reports no timings, so the logs show only SLOW -> TERMINATING -> TIMEOUT with no indication of which step stopped making progress. I could not reproduce it locally — single-node and 3-node api-v2 clusters matching CI's --kv 3 topology, cold-started, and CPU-constrained to roughly a runner's budget; ~20 runs, all completing in 1-2s with every phase in milliseconds. Rather than guess at a fix, make the next occurrence self-explaining. - Add a phase! marker around each significant step of the two tests that have hung. The ENTRY line is the point: when the test is killed, the last 'phase >' line names the step that never finished. The exit line reports the duration, distinguishing slow from stuck. - Log ensure_region_split's elapsed time and final region count, reusing the count the polling loop already fetched (diagnostics must not add a fallible request that could itself stall setup). Setup cost lands on whichever test runs first, which is the test CI kills, so this separates a slow setup from a stalled body. No client (src/) change, no assertion or control-flow change. CI already runs with RUST_LOG=info, so the markers appear without a workflow change. Signed-off-by: Eduard R. <eduard@ralphovi.net>
ti-chi-bot
Bot
added
the
dco-signoff: yes
|
[APPROVALNOTIFIER] This PR is NOT APPROVED This pull-request has been approved by: The full list of commands accepted by this bot can be found here. DetailsNeeds approval from an approver in each of these files:Approvers can indicate their approval by writing |
ti-chi-bot
Bot
added
contribution
📝 WalkthroughWalkthroughChangesTest diagnostics
Estimated code review effort: 2 (Simple) | ~10 minutes 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
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. Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
🧹 Nitpick comments (1)
tests/failpoint_tests.rs (1)
205-214: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winComplete phase coverage for the async cleanup test.
The added markers cover only the partial-commit
write_dataand lock-settling calls. The partial cleanup/verification steps at Lines [217-227], plus the no-commit and all-committed paths at Lines [175-188] and [238-250], remain unmarked; a stall there still provides no phase-level diagnosis. Wrap those remaining blocking operations or explicitly narrow the instrumentation scope.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@tests/failpoint_tests.rs` around lines 205 - 214, Complete phase instrumentation in the async cleanup test by adding phase markers around the partial cleanup and verification operations, plus the no-commit and all-committed path operations. Use descriptive phase names consistent with the existing write_data and wait_for_locks_count markers, covering every remaining blocking call identified in the test.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@tests/failpoint_tests.rs`:
- Around line 205-214: Complete phase instrumentation in the async cleanup test
by adding phase markers around the partial cleanup and verification operations,
plus the no-commit and all-committed path operations. Use descriptive phase
names consistent with the existing write_data and wait_for_locks_count markers,
covering every remaining blocking call identified in the test.
ℹ️ Review info
⚙️ Run configuration
Configuration used: defaults
Review profile: CHILL
Plan: Pro
Run ID: 3582dbaa-56aa-4f36-b540-9a15c49c0028
📒 Files selected for processing (2)
tests/common/mod.rstests/failpoint_tests.rs
|
@pingyu - another ping for awareness. This is purely for diagnostic reasons |
1 participant
failpoint_tests::txn_cleanup_2pc_locksintermittently stalls in CI until nextest's 600s cap kills it (#516;txn_cleanup_async_commit_lockshas hit the same thing). A killed test reports no timings, so the logs currently show onlySLOW → TERMINATING → TIMEOUTwith no indication of which step stopped making progress.I tried to reproduce it and could not: single-node and 3-node api-v2 clusters (matching CI's
--kv 3withconfig/tikv.toml/config/pd.toml), cold-started, and CPU-constrained to roughly a GitHub runner's budget — ~20 runs, all completing in 1–2s with every phase in milliseconds. So rather than guess at a fix, this PR makes the next occurrence self-explaining.What it adds (test-only)
phase!marker around each significant step of the two tests that have hung. The entry line is the point: when the test is killed, the lastphase >line names the step that never finished. The exit line reports the duration, distinguishing "slow" from "stuck".ensure_region_splitnow logs its elapsed time and final region count, reusing the count its polling loop already fetched — diagnostics must not add a fallible request that could itself stall setup. That cost is charged to whichever test runs first, and that is the test CI kills, so this separates "setup was slow" from "the body stalled".No client (
src/) change, no assertion or control-flow change. CI already runs withRUST_LOG=info, so the markers appear without any workflow change.Once a CI run captures a stall with these markers, the offending phase should be obvious and a real fix can follow.
Testing
Full failpoint suite green (8/8) against a local 3-node multi-region api-v2 cluster;
make checkclean; verified the markers render as intended underRUST_LOG=info.Note: this touches the same two test functions as #551, so whichever merges second will need a trivial rebase — happy to handle that.
Summary by CodeRabbit