From 0947f24687223943e74a1dc9e76decceaeb97672 Mon Sep 17 00:00:00 2001 From: "Eduard R." Date: Thu, 23 Jul 2026 00:05:39 +0200 Subject: [PATCH] tests: log phase boundaries in the cleanup tests to diagnose the CI hang MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit failpoint_tests::txn_cleanup_2pc_locks intermittently stalls in CI until nextest's 600s cap kills it (#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. --- tests/common/mod.rs | 13 ++++++- tests/failpoint_tests.rs | 79 +++++++++++++++++++++++++++++++--------- 2 files changed, 74 insertions(+), 18 deletions(-) diff --git a/tests/common/mod.rs b/tests/common/mod.rs index 69eddbe9..322c1008 100644 --- a/tests/common/mod.rs +++ b/tests/common/mod.rs @@ -113,8 +113,10 @@ async fn ensure_region_split( info!("splitting regions..."); let start_time = std::time::Instant::now(); + let mut observed_regions; loop { - if ctl::get_region_count().await? as u32 >= region_count { + observed_regions = ctl::get_region_count().await? as u32; + if observed_regions >= region_count { break; } if start_time.elapsed() > REGION_SPLIT_TIME_LIMIT { @@ -123,6 +125,15 @@ async fn ensure_region_split( } sleep(Duration::from_millis(200)).await; } + // Setup cost is charged to whichever test runs first, so record it: when that + // test is the one CI kills, this says whether the time went here or in the body. + // Reuses the count the loop already fetched — diagnostics must not add a + // fallible request that could itself fail or stall the setup. + info!( + "region split finished in {:?} ({} regions)", + start_time.elapsed(), + observed_regions + ); Ok(()) } diff --git a/tests/failpoint_tests.rs b/tests/failpoint_tests.rs index cb6a8b50..550b3d8a 100644 --- a/tests/failpoint_tests.rs +++ b/tests/failpoint_tests.rs @@ -23,6 +23,23 @@ use tikv_client::RetryOptions; use tikv_client::TransactionClient; use tikv_client::TransactionOptions; +/// Mark a phase boundary in a long-running cleanup test. +/// +/// These tests occasionally stall in CI until nextest's 600s cap kills them (#516), +/// and a killed test reports no elapsed timings — so the *entry* marker is the useful +/// one: the last `phase >` line in the log names the step that never finished. The +/// exit marker gives the duration when the test does complete, which is what tells a +/// reader whether a step is merely slow or genuinely stuck. +macro_rules! phase { + ($name:expr, $body:expr) => {{ + info!("phase > {}", $name); + let __start = std::time::Instant::now(); + let __out = $body; + info!("phase < {} in {:?}", $name, __start.elapsed()); + __out + }}; +} + #[tokio::test] #[serial] async fn txn_optimistic_heartbeat() -> Result<()> { @@ -185,10 +202,16 @@ async fn txn_cleanup_async_commit_locks() -> Result<()> { Config::default().with_default_keyspace(), ) .await?; - let keys = write_data(&client, true, false).await?; + let keys = phase!( + "async/partial: write_data", + write_data(&client, true, false).await? + ); // Wait for async commit to complete. let expected = keys.len() * percent / 100; - let remaining = wait_for_locks_count(&client, expected).await?; + let remaining = phase!( + "async/partial: wait for locks to settle", + wait_for_locks_count(&client, expected).await? + ); assert_eq!(remaining, expected); let safepoint = client.current_timestamp().await?; @@ -436,8 +459,13 @@ async fn txn_cleanup_2pc_locks() -> Result<()> { Config::default().with_default_keyspace(), ) .await?; - let keys = write_data(&client, false, true).await?; - assert_eq!(count_locks(&client).await?, keys.len()); + let keys = phase!( + "2pc/no-commit: write_data", + write_data(&client, false, true).await? + ); + phase!("2pc/no-commit: count locks", { + assert_eq!(count_locks(&client).await?, keys.len()); + }); let safepoint = client.current_timestamp().await?; { @@ -445,20 +473,27 @@ async fn txn_cleanup_2pc_locks() -> Result<()> { async_commit_only: true, // Skip 2pc locks. ..Default::default() }; - client - .cleanup_locks(full_range, &safepoint, options) - .await?; + phase!("2pc/no-commit: cleanup_locks(async_commit_only)", { + client + .cleanup_locks(full_range, &safepoint, options) + .await?; + }); assert_eq!(count_locks(&client).await?, keys.len()); } let options = ResolveLocksOptions { async_commit_only: false, ..Default::default() }; - client - .cleanup_locks(full_range, &safepoint, options) - .await?; + phase!("2pc/no-commit: cleanup_locks(all)", { + client + .cleanup_locks(full_range, &safepoint, options) + .await?; + }); - must_rollbacked(&client, keys).await; + phase!( + "2pc/no-commit: must_rollbacked", + must_rollbacked(&client, keys).await + ); assert_eq!(count_locks(&client).await?, 0); } @@ -470,19 +505,29 @@ async fn txn_cleanup_2pc_locks() -> Result<()> { Config::default().with_default_keyspace(), ) .await?; - let keys = write_data(&client, false, false).await?; - assert_eq!(wait_for_locks_count(&client, 0).await?, 0); + let keys = phase!( + "2pc/all-committed: write_data", + write_data(&client, false, false).await? + ); + phase!("2pc/all-committed: wait for locks to drain", { + assert_eq!(wait_for_locks_count(&client, 0).await?, 0); + }); let safepoint = client.current_timestamp().await?; let options = ResolveLocksOptions { async_commit_only: false, ..Default::default() }; - client - .cleanup_locks(full_range, &safepoint, options) - .await?; + phase!("2pc/all-committed: cleanup_locks(all)", { + client + .cleanup_locks(full_range, &safepoint, options) + .await?; + }); - must_committed(&client, keys).await; + phase!( + "2pc/all-committed: must_committed", + must_committed(&client, keys).await + ); assert_eq!(count_locks(&client).await?, 0); }