From 2f4fddc1dd715d5aeadfa149a55f472f692834d4 Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Fri, 6 Nov 2026 08:01:48 +1300 Subject: [PATCH 1/7] feat(worker): make the queue-storage prune lock timeout configurable Ring prune and terminal-delta rollup take their exclusive locks under a 10 ms lock_timeout that could only be changed through a hidden QueueStorage method. When short readers of the ring partitions hold a conflicting lock at that instant, prune reports blocked every tick and the rings stop recycling. Add ClientBuilder::prune_lock_timeout and the Python queue_storage_prune_lock_timeout_ms start() argument. The default stays 10 ms and zero is rejected, as with_prune_lock_timeout does. Make QueueStorage::with_prune_lock_timeout public and add set_prune_lock_timeout / prune_lock_timeout. awa.maintenance.prune.attempts already counts pruned, noop, blocked, skipped_active and already_pruned per ring; add backed_off (prune skipped by the post-skipped_active backoff) and error (prune failed with a database error) so a ring that has stopped recycling is visible for every cause. --- CHANGELOG.md | 19 ++ awa-metrics/src/lib.rs | 124 ++++++++- awa-model/src/queue_storage.rs | 26 +- awa-python/python/awa/_awa.pyi | 1 + awa-python/python/awa/client.py | 8 + awa-python/src/client.rs | 12 +- awa-python/tests/test_start_config.py | 7 + awa-worker/src/client.rs | 74 ++++++ awa-worker/src/maintenance.rs | 6 + awa-worker/src/storage.rs | 13 + awa/tests/queue_storage_runtime_test.rs | 328 ++++++++++++++++++++++++ docs/configuration.md | 6 +- docs/deployment.md | 1 + skills/awa-operations/SKILL.md | 11 + 14 files changed, 625 insertions(+), 11 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2c50c51a9..61476af16 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,25 @@ Notable changes between releases. Detailed migration notes for storage transitio ## [Unreleased] +### Added + +- **The queue-storage prune `lock_timeout` is configurable, and prune + attempts are counted by outcome for every ring.** Prune (queue, lease and + claim rings) and terminal-delta rollup take their exclusive locks under a + 10 ms `lock_timeout` that could only be changed through the hidden + `QueueStorage::with_prune_lock_timeout`. When short readers of the ring + partitions held a conflicting lock at that instant, prune reported + `blocked` every tick and the rings stopped recycling. Set it with + `ClientBuilder::prune_lock_timeout` (Rust) or + `queue_storage_prune_lock_timeout_ms` on `client.start()` (Python); the + default stays 10 ms and zero is rejected. `with_prune_lock_timeout` is now + public, with `set_prune_lock_timeout` and `prune_lock_timeout()`. + `awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome,awa_ring_reason}` + gains `backed_off` (prune skipped by the post-`skipped_active` backoff) and + `error` (prune failed with a database error) alongside the existing + `pruned`, `noop`, `blocked`, `skipped_active` and `already_pruned`. See + [Configuration](docs/configuration.md#what-the-knobs-mean). + ### Fixed - **Batch enqueues take their lane locks in one order, so they no longer diff --git a/awa-metrics/src/lib.rs b/awa-metrics/src/lib.rs index 1a1c9097b..5241d6740 100644 --- a/awa-metrics/src/lib.rs +++ b/awa-metrics/src/lib.rs @@ -251,9 +251,12 @@ pub struct AwaMetrics { /// pinned by handfuls of stragglers or by mountains of unfinished work. pub maintenance_rotate_skipped_rows: Histogram, /// Maintenance ring prune attempts, attributed to (ring, outcome, reason). - /// reason="none" for Pruned/Noop/Blocked; otherwise carries the - /// SkipReason discriminator (e.g. "queue.active_leases", - /// "queue.pending_ready", "claim.open"). + /// Outcomes: `pruned`, `noop`, `blocked` (the exclusive locks were not + /// available within the prune lock timeout), `skipped_active`, + /// `already_pruned`, `backed_off` (the tick skipped prune after repeated + /// `skipped_active` results) and `error`. reason="none" except for + /// `skipped_active`, which carries the SkipReason discriminator (e.g. + /// "queue.active_leases", "queue.pending_ready", "claim.open"). pub maintenance_prune_attempts: Counter, /// Magnitude of the reason count when prune returns SkippedActive. pub maintenance_prune_skipped_rows: Histogram, @@ -1315,16 +1318,32 @@ impl AwaMetrics { } } - /// Record an idle maintenance tick that skipped destructive prune because - /// the exact sealed generation was already reclaimed by this leader. - pub fn record_prune_already_pruned(&self, ring: &'static str) { + /// Record a maintenance tick that skipped prune because the ring's + /// backoff after repeated `skipped_active` results had not yet elapsed. + pub fn record_prune_backed_off(&self, ring: &'static str) { + self.record_prune_attempt_without_reason(ring, "backed_off"); + } + + /// Record a prune attempt that failed with a database error rather than + /// returning an outcome. + pub fn record_prune_error(&self, ring: &'static str) { + self.record_prune_attempt_without_reason(ring, "error"); + } + + fn record_prune_attempt_without_reason(&self, ring: &'static str, outcome: &'static str) { let attrs = [ opentelemetry::KeyValue::new("awa.ring", ring), - opentelemetry::KeyValue::new("awa.ring.outcome", "already_pruned"), + opentelemetry::KeyValue::new("awa.ring.outcome", outcome), opentelemetry::KeyValue::new("awa.ring.reason", "none"), ]; self.maintenance_prune_attempts.add(1, &attrs); } + + /// Record an idle maintenance tick that skipped destructive prune because + /// the exact sealed generation was already reclaimed by this leader. + pub fn record_prune_already_pruned(&self, ring: &'static str) { + self.record_prune_attempt_without_reason(ring, "already_pruned"); + } } /// No-op metrics for when OTel is not configured. @@ -1443,6 +1462,97 @@ mod tests { assert!(saw_already_pruned); } + #[test] + fn prune_attempts_count_every_outcome_per_ring() { + use awa_model::{PruneDurations, PruneOutcome, SkipReason}; + + let exporter = InMemoryMetricExporter::default(); + let provider = SdkMeterProvider::builder() + .with_periodic_exporter(exporter.clone()) + .build(); + let metrics = AwaMetrics::new(&provider.meter("awa-metrics-test")); + + for ring in ["queue", "lease", "claim"] { + metrics.record_prune_outcome( + ring, + &PruneOutcome::Pruned { + slot: 0, + generation: 1, + carried_failed_rows: 0, + durations: PruneDurations::default(), + }, + ); + metrics.record_prune_outcome(ring, &PruneOutcome::Blocked { slot: 0 }); + metrics.record_prune_outcome(ring, &PruneOutcome::Noop); + metrics.record_prune_already_pruned(ring); + metrics.record_prune_backed_off(ring); + metrics.record_prune_error(ring); + } + metrics.record_prune_outcome("claim", &PruneOutcome::Blocked { slot: 1 }); + metrics.record_prune_outcome( + "claim", + &PruneOutcome::SkippedActive { + slot: 0, + reason: SkipReason::ClaimOpen, + count: 3, + }, + ); + provider.force_flush().expect("flush metrics"); + let resource_metrics = exporter.get_finished_metrics().expect("read metrics"); + + let mut counts: std::collections::BTreeMap<(String, String, String), u64> = + std::collections::BTreeMap::new(); + for resource in &resource_metrics { + for scope in resource.scope_metrics() { + for metric in scope.metrics() { + let ( + names::MAINTENANCE_PRUNE_ATTEMPTS, + AggregatedMetrics::U64(MetricData::Sum(sum)), + ) = (metric.name(), metric.data()) + else { + continue; + }; + for point in sum.data_points() { + let label = |key: &str| { + point + .attributes() + .find(|attribute| attribute.key.as_str() == key) + .map(|attribute| attribute.value.as_str().into_owned()) + .unwrap_or_default() + }; + counts.insert( + ( + label("awa.ring"), + label("awa.ring.outcome"), + label("awa.ring.reason"), + ), + point.value(), + ); + } + } + } + } + + let count = |ring: &str, outcome: &str, reason: &str| { + counts + .get(&(ring.to_string(), outcome.to_string(), reason.to_string())) + .copied() + }; + for ring in ["queue", "lease", "claim"] { + for outcome in ["pruned", "noop", "already_pruned", "backed_off", "error"] { + assert_eq!(count(ring, outcome, "none"), Some(1), "{ring} {outcome}"); + } + let expected_blocked = if ring == "claim" { 2 } else { 1 }; + assert_eq!( + count(ring, "blocked", "none"), + Some(expected_blocked), + "{ring} blocked" + ); + } + assert_eq!(count("claim", "skipped_active", "claim.open"), Some(1)); + assert_eq!(count("queue", "skipped_active", "claim.open"), None); + } + /// A second-scale observation must not fall in the SDK's default /// millisecond-scale buckets (upper bounds 5, 10, 25, ...), and every /// histogram must export the intended explicit boundaries. diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index 339001705..07fddf860 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -3591,15 +3591,37 @@ impl QueueStorage { } } - #[doc(hidden)] + /// Set the PostgreSQL `lock_timeout` applied to the exclusive-lock steps of + /// ring prune (queue, lease and claim rings) and terminal-delta rollup. + /// + /// A prune that cannot take its locks within the timeout rolls back and + /// reports [`PruneOutcome::Blocked`]; the maintenance loop retries on its + /// next tick. The default is 10 ms, which + /// keeps prune from queueing behind readers and so from stalling claims + /// and enqueues behind its pending `ACCESS EXCLUSIVE` request. Raise it + /// when prune is persistently `Blocked` by short-lived readers of the + /// ring partitions. The timeout is applied at millisecond granularity. + /// + /// Returns a validation error for a zero timeout. pub fn with_prune_lock_timeout(mut self, timeout: Duration) -> Result { + self.set_prune_lock_timeout(timeout)?; + Ok(self) + } + + /// In-place form of [`Self::with_prune_lock_timeout`]. + pub fn set_prune_lock_timeout(&mut self, timeout: Duration) -> Result<(), AwaError> { if timeout.is_zero() { return Err(AwaError::Validation( "queue storage prune lock timeout must be greater than zero".into(), )); } self.prune_lock_timeout = timeout; - Ok(self) + Ok(()) + } + + /// The `lock_timeout` applied to prune's exclusive-lock steps. + pub fn prune_lock_timeout(&self) -> Duration { + self.prune_lock_timeout } pub fn from_existing_schema(schema: impl Into) -> Result { diff --git a/awa-python/python/awa/_awa.pyi b/awa-python/python/awa/_awa.pyi index 2219bfc3b..aa1cd7872 100644 --- a/awa-python/python/awa/_awa.pyi +++ b/awa-python/python/awa/_awa.pyi @@ -613,6 +613,7 @@ class Client: queue_storage_queue_rotate_interval_ms: int = 1000, queue_storage_lease_rotate_interval_ms: int = 250, queue_storage_claim_rotate_interval_ms: int | None = None, + queue_storage_prune_lock_timeout_ms: int | None = None, queue_storage_rotate_min_slot_age_ms: int | None = None, queue_storage_rotate_target_slot_bytes: int | None = None, queue_storage_rotate_min_slot_rows: int | None = None, diff --git a/awa-python/python/awa/client.py b/awa-python/python/awa/client.py index f734ca679..3713c97aa 100644 --- a/awa-python/python/awa/client.py +++ b/awa-python/python/awa/client.py @@ -930,6 +930,7 @@ async def start( queue_storage_queue_rotate_interval_ms: int = 1000, queue_storage_lease_rotate_interval_ms: int = 250, queue_storage_claim_rotate_interval_ms: int | None = None, + queue_storage_prune_lock_timeout_ms: int | None = None, queue_storage_rotate_min_slot_age_ms: int | None = None, queue_storage_rotate_target_slot_bytes: int | None = None, queue_storage_rotate_min_slot_rows: int | None = None, @@ -967,6 +968,12 @@ async def start( counters. Exact reads include pending deltas, so the default favors fewer hot counter updates over immediate folding. + ``queue_storage_prune_lock_timeout_ms`` sets the PostgreSQL + ``lock_timeout`` the maintenance leader uses when pruning the queue, + lease and claim rings (default 10 ms). A prune that cannot lock its + partitions in time is counted as ``blocked`` and retried on the next + tick; raise it when ``blocked`` outcomes persist. Must be > 0. + Queue dicts also accept ``claimers`` and ``claim_batch_size`` for hot queue-storage queues. ``claimers`` adds dispatcher/claimer loops that share the queue's worker permits; benchmark ``2`` or ``4`` before @@ -996,6 +1003,7 @@ async def start( queue_storage_queue_rotate_interval_ms=queue_storage_queue_rotate_interval_ms, queue_storage_lease_rotate_interval_ms=queue_storage_lease_rotate_interval_ms, queue_storage_claim_rotate_interval_ms=queue_storage_claim_rotate_interval_ms, + queue_storage_prune_lock_timeout_ms=queue_storage_prune_lock_timeout_ms, queue_storage_rotate_min_slot_age_ms=queue_storage_rotate_min_slot_age_ms, queue_storage_rotate_target_slot_bytes=queue_storage_rotate_target_slot_bytes, queue_storage_rotate_min_slot_rows=queue_storage_rotate_min_slot_rows, diff --git a/awa-python/src/client.rs b/awa-python/src/client.rs index f141508a7..cf3bc70fd 100644 --- a/awa-python/src/client.rs +++ b/awa-python/src/client.rs @@ -1796,7 +1796,7 @@ impl PyClient { }) } - #[pyo3(signature = (queues=None, *, poll_interval_ms=200, global_max_workers=None, completed_retention_hours=None, failed_retention_hours=None, descriptor_retention_days=None, cleanup_batch_size=None, leader_election_interval_ms=None, heartbeat_interval_ms=None, promote_interval_ms=None, heartbeat_rescue_interval_ms=None, heartbeat_staleness_ms=None, deadline_rescue_interval_ms=None, callback_rescue_interval_ms=None, terminal_count_rollup_interval_ms=None, queue_storage_schema=None, queue_storage_queue_slot_count=16, queue_storage_lease_slot_count=8, queue_storage_claim_slot_count=8, queue_storage_queue_stripe_count=1, queue_storage_queue_rotate_interval_ms=1000, queue_storage_lease_rotate_interval_ms=1000, queue_storage_claim_rotate_interval_ms=None, queue_storage_rotate_min_slot_age_ms=None, queue_storage_rotate_target_slot_bytes=None, queue_storage_rotate_min_slot_rows=None, queue_storage_rotate_max_slot_age_ms=None, storage_transition_role=None))] + #[pyo3(signature = (queues=None, *, poll_interval_ms=200, global_max_workers=None, completed_retention_hours=None, failed_retention_hours=None, descriptor_retention_days=None, cleanup_batch_size=None, leader_election_interval_ms=None, heartbeat_interval_ms=None, promote_interval_ms=None, heartbeat_rescue_interval_ms=None, heartbeat_staleness_ms=None, deadline_rescue_interval_ms=None, callback_rescue_interval_ms=None, terminal_count_rollup_interval_ms=None, queue_storage_schema=None, queue_storage_queue_slot_count=16, queue_storage_lease_slot_count=8, queue_storage_claim_slot_count=8, queue_storage_queue_stripe_count=1, queue_storage_queue_rotate_interval_ms=1000, queue_storage_lease_rotate_interval_ms=1000, queue_storage_claim_rotate_interval_ms=None, queue_storage_prune_lock_timeout_ms=None, queue_storage_rotate_min_slot_age_ms=None, queue_storage_rotate_target_slot_bytes=None, queue_storage_rotate_min_slot_rows=None, queue_storage_rotate_max_slot_age_ms=None, storage_transition_role=None))] #[allow(clippy::too_many_arguments)] fn start<'py>( &self, @@ -1824,6 +1824,7 @@ impl PyClient { queue_storage_queue_rotate_interval_ms: u64, queue_storage_lease_rotate_interval_ms: u64, queue_storage_claim_rotate_interval_ms: Option, + queue_storage_prune_lock_timeout_ms: Option, queue_storage_rotate_min_slot_age_ms: Option, queue_storage_rotate_target_slot_bytes: Option, queue_storage_rotate_min_slot_rows: Option, @@ -1988,6 +1989,12 @@ impl PyClient { } } + if queue_storage_prune_lock_timeout_ms == Some(0) { + return Err(pyo3::exceptions::PyValueError::new_err( + "queue_storage_prune_lock_timeout_ms must be > 0", + )); + } + builder = builder.queue_storage( QueueStorageConfig { schema: queue_storage_schema @@ -2009,6 +2016,9 @@ impl PyClient { if let Some(ms) = queue_storage_claim_rotate_interval_ms { builder = builder.claim_rotate_interval(Duration::from_millis(ms)); } + if let Some(ms) = queue_storage_prune_lock_timeout_ms { + builder = builder.prune_lock_timeout(Duration::from_millis(ms)); + } if queue_storage_rotate_min_slot_age_ms.is_some() || queue_storage_rotate_target_slot_bytes.is_some() || queue_storage_rotate_min_slot_rows.is_some() diff --git a/awa-python/tests/test_start_config.py b/awa-python/tests/test_start_config.py index 302df0fc2..889b72327 100644 --- a/awa-python/tests/test_start_config.py +++ b/awa-python/tests/test_start_config.py @@ -747,6 +747,13 @@ async def handle(job): queue_storage_claim_rotate_interval_ms=0, ) + with pytest.raises(ValueError, match="queue_storage_prune_lock_timeout_ms must be > 0"): + await client.start( + [(queue, 1)], + poll_interval_ms=25, + queue_storage_prune_lock_timeout_ms=0, + ) + with pytest.raises(ValueError, match="heartbeat_interval_ms must be > 0"): await client.start( [(queue, 1)], diff --git a/awa-worker/src/client.rs b/awa-worker/src/client.rs index 253bbde7a..75da36a68 100644 --- a/awa-worker/src/client.rs +++ b/awa-worker/src/client.rs @@ -179,6 +179,7 @@ pub struct ClientBuilder { storage: RuntimeStorage, ring_rotation_cadence: RingRotationCadence, claim_rotate_interval: Option, + prune_lock_timeout: Option, transition_role: TransitionWorkerRole, storage_error: Option, health_addr: Option, @@ -242,6 +243,7 @@ impl ClientBuilder { storage, ring_rotation_cadence: RingRotationCadence::DEFAULT, claim_rotate_interval: None, + prune_lock_timeout: None, transition_role: TransitionWorkerRole::Auto, storage_error, health_addr: None, @@ -978,6 +980,25 @@ impl ClientBuilder { self } + /// Override the PostgreSQL `lock_timeout` the maintenance leader applies to + /// the exclusive-lock steps of queue, lease and claim ring prune and of + /// terminal-delta rollup (default 10 ms). + /// + /// A prune that cannot take its locks within the timeout rolls back and is + /// recorded as `blocked` in `awa.maintenance.prune.attempts`; it retries on + /// the next maintenance tick. The short default keeps the pending + /// `ACCESS EXCLUSIVE` request from stalling claims and enqueues behind it. + /// Raise it when `blocked` outcomes persist and the rings stop recycling + /// because short-lived readers (admin queries, dashboards) repeatedly hold + /// the ring partitions at the moment prune tries. A zero timeout makes + /// [`Self::build`] fail. Only takes effect when queue storage is active. + /// May be set before or after [`Self::queue_storage`]; retained across + /// storage configuration changes. + pub fn prune_lock_timeout(mut self, timeout: Duration) -> Self { + self.prune_lock_timeout = Some(timeout); + self + } + /// Override when a maintenance tick may seal the current slot of the /// queue, lease and claim rings (default /// [`RingRotationCadence::DEFAULT`]: five seconds of observed filling @@ -1091,6 +1112,11 @@ impl ClientBuilder { if let Some(interval) = self.claim_rotate_interval { runtime.claim_rotate_interval = interval; } + if let Some(timeout) = self.prune_lock_timeout { + runtime + .set_prune_lock_timeout(timeout) + .map_err(|err| BuildError::InvalidQueueStorage(err.to_string()))?; + } } let mut queue_names = HashSet::with_capacity(self.queues.len()); @@ -2971,6 +2997,54 @@ mod tests { assert!(client.storage.queue_storage().is_none()); } + #[tokio::test] + async fn prune_lock_timeout_reaches_the_store_in_either_builder_order() { + let timeout = Duration::from_millis(750); + for configure_first in [true, false] { + let mut builder = Client::builder(lazy_pool()).queue("q", QueueConfig::default()); + if configure_first { + builder = builder.prune_lock_timeout(timeout); + } + builder = builder.queue_storage( + QueueStorageConfig::default(), + Duration::from_secs(3), + Duration::from_secs(7), + ); + if !configure_first { + builder = builder.prune_lock_timeout(timeout); + } + let client = builder.build().unwrap(); + let store = client.storage.queue_storage_store().unwrap(); + assert_eq!(store.prune_lock_timeout(), timeout); + } + + let client = Client::builder(lazy_pool()) + .queue("q", QueueConfig::default()) + .build() + .unwrap(); + assert_eq!( + client + .storage + .queue_storage_store() + .unwrap() + .prune_lock_timeout(), + Duration::from_millis(10) + ); + } + + #[tokio::test] + async fn zero_prune_lock_timeout_is_rejected_at_build() { + let result = Client::builder(lazy_pool()) + .queue("q", QueueConfig::default()) + .prune_lock_timeout(Duration::ZERO) + .build(); + assert!( + matches!(result, Err(BuildError::InvalidQueueStorage(ref message)) if message.contains("prune lock timeout")), + "{:?}", + result.err() + ); + } + #[tokio::test] async fn register_accepts_send_non_sync_handler_future() { #[derive(serde::Serialize, serde::Deserialize, awa_macros::JobArgs)] diff --git a/awa-worker/src/maintenance.rs b/awa-worker/src/maintenance.rs index d84960d37..f1dfe9f79 100644 --- a/awa-worker/src/maintenance.rs +++ b/awa-worker/src/maintenance.rs @@ -2863,6 +2863,7 @@ impl MaintenanceService { if prune_tracker.should_skip(PRUNE_BRANCH_QUEUE) { debug!(branch = PRUNE_BRANCH_QUEUE, "Prune backed off this tick"); + self.metrics.record_prune_backed_off("queue"); return; } @@ -2910,6 +2911,7 @@ impl MaintenanceService { } } Err(err) => { + self.metrics.record_prune_error("queue"); error!(error = %err, "Failed to prune queue storage queue segments"); } } @@ -2978,6 +2980,7 @@ impl MaintenanceService { if prune_tracker.should_skip(PRUNE_BRANCH_LEASE) { debug!(branch = PRUNE_BRANCH_LEASE, "Prune backed off this tick"); + self.metrics.record_prune_backed_off("lease"); return; } @@ -3008,6 +3011,7 @@ impl MaintenanceService { } } Err(err) => { + self.metrics.record_prune_error("lease"); error!(error = %err, "Failed to prune queue storage lease segments"); } } @@ -3081,6 +3085,7 @@ impl MaintenanceService { if prune_tracker.should_skip(PRUNE_BRANCH_CLAIM) { debug!(branch = PRUNE_BRANCH_CLAIM, "Prune backed off this tick"); + self.metrics.record_prune_backed_off("claim"); return; } @@ -3111,6 +3116,7 @@ impl MaintenanceService { } } Err(err) => { + self.metrics.record_prune_error("claim"); error!(error = %err, "Failed to prune queue storage claim segments"); } } diff --git a/awa-worker/src/storage.rs b/awa-worker/src/storage.rs index ac0f4520d..2a7c51a87 100644 --- a/awa-worker/src/storage.rs +++ b/awa-worker/src/storage.rs @@ -30,6 +30,19 @@ impl QueueStorageRuntime { rotation_cadence: RingRotationCadence::default(), }) } + + /// Set the prune `lock_timeout` on the store. Only valid before the store + /// is shared, which holds for a runtime still owned by the builder. + pub fn set_prune_lock_timeout(&mut self, timeout: Duration) -> Result<(), awa_model::AwaError> { + Arc::get_mut(&mut self.store) + .ok_or_else(|| { + awa_model::AwaError::Validation( + "queue storage is already shared; set the prune lock timeout before build" + .into(), + ) + })? + .set_prune_lock_timeout(timeout) + } } #[derive(Debug, Clone, Default)] diff --git a/awa/tests/queue_storage_runtime_test.rs b/awa/tests/queue_storage_runtime_test.rs index bf51546fe..97ccf36f0 100644 --- a/awa/tests/queue_storage_runtime_test.rs +++ b/awa/tests/queue_storage_runtime_test.rs @@ -15569,6 +15569,334 @@ async fn test_queue_storage_claimer_heartbeat_skips_fresh_lease() { ); } +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_runtime_counts_blocked_then_pruned_lease_prune_attempts() { + let (_db_guard, pool) = setup_pool(10).await; + let queue = "qs_prune_attempt_metric"; + let schema = "awa_qs_prune_attempt_metric"; + let store_config = QueueStorageConfig { + schema: schema.to_string(), + queue_slot_count: 4, + lease_slot_count: 2, + lease_claim_receipts: false, + ..Default::default() + }; + let store = create_store_with_config(&pool, store_config.clone()).await; + + let mut reader_tx = pool.begin().await.expect("begin reader tx"); + sqlx::query(audited_sql(format!( + "LOCK TABLE {schema}.leases_0, {schema}.leases_1 IN ACCESS SHARE MODE" + ))) + .execute(reader_tx.as_mut()) + .await + .expect("reader lock"); + + let (exporter, meter_provider) = install_in_memory_metrics(); + let client = Client::builder(pool.clone()) + .queue( + queue, + QueueConfig { + max_workers: 4, + poll_interval: Duration::from_millis(25), + ..QueueConfig::default() + }, + ) + .queue_storage( + store_config, + Duration::from_secs(60), + Duration::from_millis(50), + ) + .claim_rotate_interval(Duration::from_secs(60)) + .ring_rotation_cadence(RingRotationCadence::EAGER) + .prune_lock_timeout(Duration::from_millis(20)) + .register_worker(CompleteWorker) + .promote_interval(Duration::from_millis(25)) + .leader_election_interval(Duration::from_millis(100)) + .leader_check_interval(Duration::from_millis(50)) + .heartbeat_rescue_interval(Duration::from_millis(100)) + .deadline_rescue_interval(Duration::from_millis(100)) + .callback_rescue_interval(Duration::from_millis(25)) + .build() + .expect("build prune metric client"); + client.start().await.expect("start prune metric client"); + + let job_id = enqueue_job( + &pool, + &store, + &CompleteJob { id: 4001 }, + InsertOpts { + queue: queue.to_string(), + ..Default::default() + }, + ) + .await; + wait_for_job_state( + &store, + &pool, + job_id, + &[JobState::Completed], + Duration::from_secs(15), + ) + .await; + + let lease_attempts = |outcome: &str| { + meter_provider.force_flush().expect("flush metrics"); + let resource_metrics = exporter.get_finished_metrics().expect("read metrics"); + let mut total = 0; + for resource in &resource_metrics { + for scope in resource.scope_metrics() { + for metric in scope.metrics() { + if metric.name() != "awa.maintenance.prune.attempts" { + continue; + } + let AggregatedMetrics::U64(MetricData::Sum(sum)) = metric.data() else { + continue; + }; + total += sum + .data_points() + .filter(|point| { + let has = |key: &str, value: &str| { + point + .attributes() + .any(|kv| kv.key.as_str() == key && kv.value.as_str() == value) + }; + has("awa.ring", "lease") && has("awa.ring.outcome", outcome) + }) + .map(|point| point.value()) + .sum::(); + } + } + } + total + }; + + let deadline = Instant::now() + Duration::from_secs(20); + while lease_attempts("blocked") == 0 { + assert!( + Instant::now() < deadline, + "lease prune never reported blocked while a reader held the lease partition" + ); + tokio::time::sleep(Duration::from_millis(100)).await; + } + assert_eq!(lease_attempts("pruned"), 0); + + reader_tx.rollback().await.expect("release reader lock"); + let deadline = Instant::now() + Duration::from_secs(20); + while lease_attempts("pruned") == 0 { + assert!( + Instant::now() < deadline, + "lease prune never completed after the reader released" + ); + tokio::time::sleep(Duration::from_millis(100)).await; + } + + client.shutdown(Duration::from_secs(5)).await; +} + +#[derive(Clone, Copy, Debug)] +enum PruneRing { + Queue, + Lease, + Claim, +} + +async fn prune_ring( + store: &QueueStorage, + pool: &sqlx::PgPool, + ring: PruneRing, +) -> Result { + match ring { + PruneRing::Queue => store.prune_oldest(pool, Duration::ZERO).await, + PruneRing::Lease => store.prune_oldest_leases(pool).await, + PruneRing::Claim => store.prune_oldest_claims(pool).await, + } +} + +/// A reader holds `locked_relation` so prune must wait for its exclusive lock. +/// With a short timeout prune gives up as `Blocked` only after that timeout; +/// with a long timeout it waits out a reader that releases part-way and then +/// completes. +async fn assert_prune_waits_for_configured_lock_timeout( + pool: &sqlx::PgPool, + config: &QueueStorageConfig, + ring: PruneRing, + locked_relation: &str, +) { + let short_timeout = Duration::from_millis(300); + let short_store = QueueStorage::new(config.clone()) + .expect("short-timeout store") + .with_prune_lock_timeout(short_timeout) + .expect("short prune lock timeout"); + assert_eq!(short_store.prune_lock_timeout(), short_timeout); + + let mut reader_tx = pool.begin().await.expect("begin reader tx"); + sqlx::query(audited_sql(format!( + "LOCK TABLE {locked_relation} IN ACCESS SHARE MODE" + ))) + .execute(reader_tx.as_mut()) + .await + .expect("reader lock"); + + let started = Instant::now(); + let blocked = prune_ring(&short_store, pool, ring) + .await + .expect("prune under reader lock"); + let elapsed = started.elapsed(); + assert!( + matches!(blocked, PruneOutcome::Blocked { .. }), + "{ring:?} prune must report Blocked while the reader holds its lock, got {blocked:?}" + ); + assert!( + elapsed >= short_timeout, + "{ring:?} prune gave up after {elapsed:?}, before the {short_timeout:?} lock timeout" + ); + assert!( + elapsed < Duration::from_secs(10), + "{ring:?} prune waited {elapsed:?} for a {short_timeout:?} lock timeout" + ); + + let long_store = QueueStorage::new(config.clone()) + .expect("long-timeout store") + .with_prune_lock_timeout(Duration::from_secs(60)) + .expect("long prune lock timeout"); + let reader_hold = Duration::from_millis(600); + let release = tokio::spawn(async move { + tokio::time::sleep(reader_hold).await; + reader_tx.rollback().await.expect("release reader lock"); + }); + let started = Instant::now(); + let outcome = prune_ring(&long_store, pool, ring) + .await + .expect("prune after reader release"); + let elapsed = started.elapsed(); + release.await.expect("release task"); + assert!( + !matches!(outcome, PruneOutcome::Blocked { .. }), + "{ring:?} prune with a long lock timeout must outwait the reader, got {outcome:?}" + ); + assert!( + elapsed >= short_timeout, + "{ring:?} prune returned after {elapsed:?} instead of waiting for the reader" + ); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_queue_prune_lock_timeout_is_configurable() { + let (_db_guard, pool) = setup_pool(8).await; + let schema = "awa_qs_prune_lt_queue"; + let store = create_store(&pool, schema).await; + store.enqueue_batch(&pool, "q", 1, 1).await.unwrap(); + let claims = store.claim_batch(&pool, "q", 1).await.unwrap(); + assert_eq!(store.complete_batch(&pool, &claims).await.unwrap(), 1); + assert!(matches!( + store.rotate(&pool).await.unwrap(), + RotateOutcome::Rotated { .. } + )); + + let config = QueueStorageConfig { + schema: schema.to_string(), + queue_slot_count: 4, + lease_slot_count: 2, + lease_claim_receipts: false, + ..Default::default() + }; + assert_prune_waits_for_configured_lock_timeout( + &pool, + &config, + PruneRing::Queue, + &format!("{schema}.ready_segments_0"), + ) + .await; +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_lease_prune_lock_timeout_is_configurable() { + let (_db_guard, pool) = setup_pool(8).await; + let schema = "awa_qs_prune_lt_lease"; + let store = create_store(&pool, schema).await; + store.enqueue_batch(&pool, "q", 1, 2).await.unwrap(); + let claimed = store + .claim_runtime_batch(&pool, "q", 2, Duration::from_secs(60)) + .await + .unwrap(); + assert_eq!(claimed.len(), 2); + store.complete_runtime_batch(&pool, &claimed).await.unwrap(); + let cadence = RingRotationCadence::EAGER + .with_min_slot_age(Duration::from_secs(3600)) + .with_target_slot_bytes(1 << 30) + .with_min_slot_rows(0) + .with_max_slot_age(Duration::ZERO); + assert!(matches!( + store + .rotate_leases_with_cadence(&pool, cadence) + .await + .unwrap(), + RotateOutcome::Rotated { slot: 1, .. } + )); + + let config = QueueStorageConfig { + schema: schema.to_string(), + queue_slot_count: 4, + lease_slot_count: 2, + lease_claim_receipts: false, + ..Default::default() + }; + assert_prune_waits_for_configured_lock_timeout( + &pool, + &config, + PruneRing::Lease, + &format!("{schema}.leases_0"), + ) + .await; +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_claim_prune_lock_timeout_is_configurable() { + let (_db_guard, pool) = setup_pool(8).await; + let schema = "awa_qs_prune_lt_claim"; + let config = QueueStorageConfig { + schema: schema.to_string(), + queue_slot_count: 4, + lease_slot_count: 2, + claim_slot_count: 4, + lease_claim_receipts: true, + ..Default::default() + }; + create_store_with_config(&pool, config.clone()).await; + sqlx::query(audited_sql(format!( + r#" + INSERT INTO {schema}.lease_claims ( + claim_slot, job_id, run_lease, ready_slot, ready_generation, + queue, priority, attempt, max_attempts, lane_seq + ) VALUES (0, 1001, 1, 0, 0, 'synthetic', 2, 1, 25, 1001) + "# + ))) + .execute(&pool) + .await + .expect("seed claim"); + sqlx::query(audited_sql(format!( + "INSERT INTO {schema}.lease_claim_closures (claim_slot, job_id, run_lease, outcome) \ + VALUES (0, 1001, 1, 'completed')" + ))) + .execute(&pool) + .await + .expect("seed closure"); + sqlx::query(audited_sql(format!( + "INSERT INTO {schema}.claim_ring_rotations (generation, slot) VALUES (1, 1)" + ))) + .execute(&pool) + .await + .expect("advance claim ring cursor away from slot 0"); + + assert_prune_waits_for_configured_lock_timeout( + &pool, + &config, + PruneRing::Claim, + &format!("{schema}.lease_claims_0"), + ) + .await; +} + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn test_queue_storage_prune_oldest_blocks_on_reader_lock() { let (_db_guard, pool) = setup_pool(10).await; diff --git a/docs/configuration.md b/docs/configuration.md index 930bc6bde..fc120bd15 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -548,6 +548,7 @@ let client = Client::builder(pool.clone()) Duration::from_millis(1_000), ) .claim_rotate_interval(Duration::from_millis(1_000)) + .prune_lock_timeout(Duration::from_millis(10)) .build()?; ``` @@ -564,6 +565,7 @@ await client.start( queue_storage_queue_rotate_interval_ms=1000, queue_storage_lease_rotate_interval_ms=1000, queue_storage_claim_rotate_interval_ms=1000, + queue_storage_prune_lock_timeout_ms=10, ) ``` @@ -579,11 +581,12 @@ await client.start( | `queue_rotate_interval` | `1000ms` | How often ready/terminal segments rotate | | `lease_rotate_interval` | `1000ms` | How often lease segments rotate | | `claim_rotate_interval` | matches `queue_rotate_interval` | How often the ADR-023 claim-ring rotates. Set with `ClientBuilder::claim_rotate_interval` (Rust) or `queue_storage_claim_rotate_interval_ms` (Python). Test harnesses sometimes set this to a long interval to pin claim-ring layout for deterministic count assertions. | +| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas). A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | | `ring_rotation_cadence` | 5 s / 2 MiB target / 256 rows / 60 s | A non-empty slot becomes eligible after `min_slot_age` since the first non-empty observation once it holds `min_slot_rows`, when `target_slot_bytes` is reached, or after `max_slot_age` regardless of rows (so a trickle of writes neither seals a nearly empty slot every window nor keeps one open indefinitely). Python: `queue_storage_rotate_min_slot_rows`, `queue_storage_rotate_max_slot_age_ms`. Counts total physical storage, including indexes and TOAST. Empty slots bypass the cadence. The minimum age uses a monotonic clock and resets on an empty observation or leader change; `max_slot_age` also counts from when the slot opened on the database clock, so a leader change does not restart it, except under compat (pre-flip) authority when an older rotator left no ledger row for the slot. `max_slot_age` makes a slot eligible to seal; the busy and reuse checks still decide when it is reclaimed. Configure with `ClientBuilder::ring_rotation_cadence` (Rust) or `queue_storage_rotate_min_slot_age_ms` / `queue_storage_rotate_target_slot_bytes` (Python). A zero byte target disables the size trigger, a zero `min_slot_rows` disables the row floor, and a zero `max_slot_age` disables the ceiling. A row floor needs a size target or a ceiling, and a queue-storage client refuses to build without one, because lease rows are deleted as attempts finish and a lease slot may never reach the floor. A zero `min_slot_age`, or `RingRotationCadence::EAGER`, permits sealing on every tick whatever the other settings. The target is sampled and does not bound retained storage. | The benchmark harness in [postgresql-job-queue-benchmarking](https://github.com/hardbyte/postgresql-job-queue-benchmarking) reads `QUEUE_SLOT_COUNT`, `LEASE_SLOT_COUNT`, `CLAIM_SLOT_COUNT`, `QUEUE_STRIPE_COUNT`, and `LEASE_CLAIM_RECEIPTS` from the environment. Those env vars are benchmark configuration, not general worker-runtime configuration. -Rust builder overrides for cadence and claim rotation interval may be set before +Rust builder overrides for cadence, claim rotation interval and prune lock timeout may be set before or after `queue_storage`; reconfiguring storage preserves those overrides. With no claim interval override, the claim ring uses the queue decision interval. @@ -593,6 +596,7 @@ Use the defaults unless you have a reason not to: - Increase `lease_slot_count` if lease churn is high enough that dead tuples in the lease ring stop collapsing promptly. - Increase `claim_slot_count` if the rotation cadence (`claim_rotate_interval`) plus the slot count combine to a partition retention window shorter than your longest in-flight zero-deadline short job; running out of empty slots forces `rotate_claims` to return `SkippedBusy` and the receipt-plane churn falls back onto a smaller working set of partitions. - Increase `queue_stripe_count` only for measured workloads where many small replicas contend on the same logical queue. This is queue-storage configuration, not a per-queue `QueueConfig` field: it gives each logical queue the same number of physical stripes. Striping spreads a hot logical queue over `queue#N` physical coordination paths, but it weakens perfect global ordering and can regress calmer shapes if overused. For single hot-queue workloads, benchmark `2` stripes first; higher values should be treated as workload-specific tuning rather than a general default. +- Increase `prune_lock_timeout` when `awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}` stays non-zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Raise it in steps (for example `100ms`, then `1s`) and keep it well below the time you can tolerate claims and enqueues queueing behind prune; while prune waits, new accesses to the same partition queue behind its lock request. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. - Increase rotation intervals to reduce partition churn and metadata activity. - Decrease rotation intervals to tighten dead-tuple bounds at the cost of more frequent rotate/prune work. diff --git a/docs/deployment.md b/docs/deployment.md index 5d1123cfa..48d5c6e47 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -82,6 +82,7 @@ Recommended practice: - monitor `pg_stat_activity` for long transactions - monitor `pg_stat_user_tables` on the active queue-storage schema; ready, tombstone, done, and terminal-delta segments should stay near zero dead tuples, lease segments may spike within the rotation window but should collapse after prune, and `attempt_state` should roughly track live long-running attempts - tune autovacuum for the database if the lease tables churn heavily +- alert on `awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}` (and `error`) sustained above zero: the rings are not recycling. If short readers of the ring partitions are the cause, raise [`prune_lock_timeout`](configuration.md#what-the-knobs-mean) Queue-storage depth metrics are designed for high-cadence monitoring. The worker records `available` from lane-head cursor differences and probes queue lag from the next claimable row per lane, instead of running the exact `queue_counts` ready-row scan on every metrics tick. Use the admin API or CLI when you need exact queue counts for an operator action. diff --git a/skills/awa-operations/SKILL.md b/skills/awa-operations/SKILL.md index 4cfb039b0..17f8ec231 100644 --- a/skills/awa-operations/SKILL.md +++ b/skills/awa-operations/SKILL.md @@ -290,6 +290,17 @@ Rings rotate only when active — a frozen generation on an idle queue is health The condition to alert on is a frozen generation *with* accumulating rows (`skipped_busy`): a pinned ring, almost always caused by a long-held snapshot. +## Prune Lock Timeout + +Ring prune takes exclusive locks under a `lock_timeout` of 10 ms by default; +when it cannot, it rolls back and counts `blocked` in +`awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome}`. Persistent +`blocked` (or `error`) means the rings are not recycling. Raise +`ClientBuilder::prune_lock_timeout` (Python +`queue_storage_prune_lock_timeout_ms`) in steps when short readers of the ring +partitions are the cause. `backed_off` means prune was skipped for a few ticks +after repeated `skipped_active`. + ## Ring Rotation Cadence For queue storage, `ClientBuilder::ring_rotation_cadence` seals a slot after a From 72bd415340c7fd5c4f3dca5649f9a2240bc7176a Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Fri, 6 Nov 2026 09:06:29 +1300 Subject: [PATCH 2/7] test(worker): serialise tests that install a global meter provider --- awa/tests/queue_storage_runtime_test.rs | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/awa/tests/queue_storage_runtime_test.rs b/awa/tests/queue_storage_runtime_test.rs index 97ccf36f0..e122a9ea7 100644 --- a/awa/tests/queue_storage_runtime_test.rs +++ b/awa/tests/queue_storage_runtime_test.rs @@ -40,6 +40,10 @@ struct RawReceiptClaimRow { claim_slot: i32, } +/// `AwaMetrics::from_global` reads the process-wide meter provider when a +/// client starts, so tests that install their own provider must not overlap. +static GLOBAL_METRICS_TEST_LOCK: Mutex<()> = Mutex::const_new(()); + fn install_in_memory_metrics() -> (InMemoryMetricExporter, SdkMeterProvider) { let exporter = InMemoryMetricExporter::default(); let meter_provider = SdkMeterProvider::builder() @@ -7625,6 +7629,7 @@ async fn test_queue_storage_cancelled_compact_claim_closes_via_batch_and_queue_p #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn test_queue_storage_capacity_wake_drains_after_partial_drain() { + let _metrics_guard = GLOBAL_METRICS_TEST_LOCK.lock().await; let (exporter, meter_provider) = install_in_memory_metrics(); let (_db_guard, pool) = setup_pool(10).await; let queue = "qs_capacity_wake_partial_drain"; @@ -15591,6 +15596,7 @@ async fn test_runtime_counts_blocked_then_pruned_lease_prune_attempts() { .await .expect("reader lock"); + let _metrics_guard = GLOBAL_METRICS_TEST_LOCK.lock().await; let (exporter, meter_provider) = install_in_memory_metrics(); let client = Client::builder(pool.clone()) .queue( From 96a8d5060f6413a9aa1cdc402f4886c728f21314 Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Fri, 6 Nov 2026 11:51:55 +1300 Subject: [PATCH 3/7] fix(worker): bound the prune lock timeout and tighten its docs and tests --- awa-model/src/queue_storage.rs | 13 +++++++- awa-worker/src/client.rs | 40 +++++++++++++++++++------ awa/tests/queue_storage_runtime_test.rs | 8 +++-- docs/configuration.md | 4 +-- docs/deployment.md | 2 +- skills/awa-operations/SKILL.md | 7 +++-- 6 files changed, 56 insertions(+), 18 deletions(-) diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index 07fddf860..2e5158ced 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -3594,6 +3594,10 @@ impl QueueStorage { /// Set the PostgreSQL `lock_timeout` applied to the exclusive-lock steps of /// ring prune (queue, lease and claim rings) and terminal-delta rollup. /// + /// Queue ring prune waits only on its `ready_segments` lock; its other + /// partition locks use `NOWAIT`, so a reader holding one of them makes it + /// `Blocked` immediately whatever the timeout. + /// /// A prune that cannot take its locks within the timeout rolls back and /// reports [`PruneOutcome::Blocked`]; the maintenance loop retries on its /// next tick. The default is 10 ms, which @@ -3602,7 +3606,8 @@ impl QueueStorage { /// when prune is persistently `Blocked` by short-lived readers of the /// ring partitions. The timeout is applied at millisecond granularity. /// - /// Returns a validation error for a zero timeout. + /// Returns a validation error for a zero timeout or one above PostgreSQL's + /// `lock_timeout` maximum (`i32::MAX` milliseconds, about 24.8 days). pub fn with_prune_lock_timeout(mut self, timeout: Duration) -> Result { self.set_prune_lock_timeout(timeout)?; Ok(self) @@ -3615,6 +3620,12 @@ impl QueueStorage { "queue storage prune lock timeout must be greater than zero".into(), )); } + if timeout.as_millis() > i32::MAX as u128 { + return Err(AwaError::Validation(format!( + "queue storage prune lock timeout must not exceed {} ms", + i32::MAX + ))); + } self.prune_lock_timeout = timeout; Ok(()) } diff --git a/awa-worker/src/client.rs b/awa-worker/src/client.rs index 75da36a68..f5c822784 100644 --- a/awa-worker/src/client.rs +++ b/awa-worker/src/client.rs @@ -984,13 +984,18 @@ impl ClientBuilder { /// the exclusive-lock steps of queue, lease and claim ring prune and of /// terminal-delta rollup (default 10 ms). /// + /// Queue ring prune waits only on its `ready_segments` lock; its other + /// partition locks use `NOWAIT`, so a reader holding one of them makes it + /// `blocked` immediately whatever the timeout. + /// /// A prune that cannot take its locks within the timeout rolls back and is /// recorded as `blocked` in `awa.maintenance.prune.attempts`; it retries on /// the next maintenance tick. The short default keeps the pending /// `ACCESS EXCLUSIVE` request from stalling claims and enqueues behind it. /// Raise it when `blocked` outcomes persist and the rings stop recycling /// because short-lived readers (admin queries, dashboards) repeatedly hold - /// the ring partitions at the moment prune tries. A zero timeout makes + /// the ring partitions at the moment prune tries. A zero timeout, or one above + /// PostgreSQL's `lock_timeout` maximum (`i32::MAX` ms), makes /// [`Self::build`] fail. Only takes effect when queue storage is active. /// May be set before or after [`Self::queue_storage`]; retained across /// storage configuration changes. @@ -3033,15 +3038,32 @@ mod tests { } #[tokio::test] - async fn zero_prune_lock_timeout_is_rejected_at_build() { - let result = Client::builder(lazy_pool()) + async fn out_of_range_prune_lock_timeout_is_rejected_at_build() { + for timeout in [Duration::ZERO, Duration::from_millis(i32::MAX as u64 + 1)] { + let result = Client::builder(lazy_pool()) + .queue("q", QueueConfig::default()) + .prune_lock_timeout(timeout) + .build(); + assert!( + matches!(result, Err(BuildError::InvalidQueueStorage(ref message)) if message.contains("prune lock timeout")), + "{timeout:?}: {:?}", + result.err() + ); + } + + let at_maximum = Duration::from_millis(i32::MAX as u64); + let client = Client::builder(lazy_pool()) .queue("q", QueueConfig::default()) - .prune_lock_timeout(Duration::ZERO) - .build(); - assert!( - matches!(result, Err(BuildError::InvalidQueueStorage(ref message)) if message.contains("prune lock timeout")), - "{:?}", - result.err() + .prune_lock_timeout(at_maximum) + .build() + .unwrap(); + assert_eq!( + client + .storage + .queue_storage_store() + .unwrap() + .prune_lock_timeout(), + at_maximum ); } diff --git a/awa/tests/queue_storage_runtime_test.rs b/awa/tests/queue_storage_runtime_test.rs index e122a9ea7..9f106bd92 100644 --- a/awa/tests/queue_storage_runtime_test.rs +++ b/awa/tests/queue_storage_runtime_test.rs @@ -15727,6 +15727,7 @@ async fn assert_prune_waits_for_configured_lock_timeout( config: &QueueStorageConfig, ring: PruneRing, locked_relation: &str, + expected_after_release: fn(&PruneOutcome) -> bool, ) { let short_timeout = Duration::from_millis(300); let short_store = QueueStorage::new(config.clone()) @@ -15777,8 +15778,8 @@ async fn assert_prune_waits_for_configured_lock_timeout( let elapsed = started.elapsed(); release.await.expect("release task"); assert!( - !matches!(outcome, PruneOutcome::Blocked { .. }), - "{ring:?} prune with a long lock timeout must outwait the reader, got {outcome:?}" + expected_after_release(&outcome), + "{ring:?} prune with a long lock timeout must outwait the reader and finish, got {outcome:?}" ); assert!( elapsed >= short_timeout, @@ -15811,6 +15812,7 @@ async fn test_queue_prune_lock_timeout_is_configurable() { &config, PruneRing::Queue, &format!("{schema}.ready_segments_0"), + |outcome| matches!(outcome, PruneOutcome::Pruned { .. }), ) .await; } @@ -15852,6 +15854,7 @@ async fn test_lease_prune_lock_timeout_is_configurable() { &config, PruneRing::Lease, &format!("{schema}.leases_0"), + |outcome| matches!(outcome, PruneOutcome::Pruned { .. }), ) .await; } @@ -15899,6 +15902,7 @@ async fn test_claim_prune_lock_timeout_is_configurable() { &config, PruneRing::Claim, &format!("{schema}.lease_claims_0"), + |outcome| matches!(outcome, PruneOutcome::Pruned { .. }), ) .await; } diff --git a/docs/configuration.md b/docs/configuration.md index fc120bd15..68eec547f 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -581,7 +581,7 @@ await client.start( | `queue_rotate_interval` | `1000ms` | How often ready/terminal segments rotate | | `lease_rotate_interval` | `1000ms` | How often lease segments rotate | | `claim_rotate_interval` | matches `queue_rotate_interval` | How often the ADR-023 claim-ring rotates. Set with `ClientBuilder::claim_rotate_interval` (Rust) or `queue_storage_claim_rotate_interval_ms` (Python). Test harnesses sometimes set this to a long interval to pin claim-ring layout for deterministic count assertions. | -| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas). A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | +| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | | `ring_rotation_cadence` | 5 s / 2 MiB target / 256 rows / 60 s | A non-empty slot becomes eligible after `min_slot_age` since the first non-empty observation once it holds `min_slot_rows`, when `target_slot_bytes` is reached, or after `max_slot_age` regardless of rows (so a trickle of writes neither seals a nearly empty slot every window nor keeps one open indefinitely). Python: `queue_storage_rotate_min_slot_rows`, `queue_storage_rotate_max_slot_age_ms`. Counts total physical storage, including indexes and TOAST. Empty slots bypass the cadence. The minimum age uses a monotonic clock and resets on an empty observation or leader change; `max_slot_age` also counts from when the slot opened on the database clock, so a leader change does not restart it, except under compat (pre-flip) authority when an older rotator left no ledger row for the slot. `max_slot_age` makes a slot eligible to seal; the busy and reuse checks still decide when it is reclaimed. Configure with `ClientBuilder::ring_rotation_cadence` (Rust) or `queue_storage_rotate_min_slot_age_ms` / `queue_storage_rotate_target_slot_bytes` (Python). A zero byte target disables the size trigger, a zero `min_slot_rows` disables the row floor, and a zero `max_slot_age` disables the ceiling. A row floor needs a size target or a ceiling, and a queue-storage client refuses to build without one, because lease rows are deleted as attempts finish and a lease slot may never reach the floor. A zero `min_slot_age`, or `RingRotationCadence::EAGER`, permits sealing on every tick whatever the other settings. The target is sampled and does not bound retained storage. | The benchmark harness in [postgresql-job-queue-benchmarking](https://github.com/hardbyte/postgresql-job-queue-benchmarking) reads `QUEUE_SLOT_COUNT`, `LEASE_SLOT_COUNT`, `CLAIM_SLOT_COUNT`, `QUEUE_STRIPE_COUNT`, and `LEASE_CLAIM_RECEIPTS` from the environment. Those env vars are benchmark configuration, not general worker-runtime configuration. @@ -596,7 +596,7 @@ Use the defaults unless you have a reason not to: - Increase `lease_slot_count` if lease churn is high enough that dead tuples in the lease ring stop collapsing promptly. - Increase `claim_slot_count` if the rotation cadence (`claim_rotate_interval`) plus the slot count combine to a partition retention window shorter than your longest in-flight zero-deadline short job; running out of empty slots forces `rotate_claims` to return `SkippedBusy` and the receipt-plane churn falls back onto a smaller working set of partitions. - Increase `queue_stripe_count` only for measured workloads where many small replicas contend on the same logical queue. This is queue-storage configuration, not a per-queue `QueueConfig` field: it gives each logical queue the same number of physical stripes. Striping spreads a hot logical queue over `queue#N` physical coordination paths, but it weakens perfect global ordering and can regress calmer shapes if overused. For single hot-queue workloads, benchmark `2` stripes first; higher values should be treated as workload-specific tuning rather than a general default. -- Increase `prune_lock_timeout` when `awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}` stays non-zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Raise it in steps (for example `100ms`, then `1s`) and keep it well below the time you can tolerate claims and enqueues queueing behind prune; while prune waits, new accesses to the same partition queue behind its lock request. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. +- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in steps (for example `100ms`, then `1s`) and keep it well below the time you can tolerate claims and enqueues queueing behind prune; while prune waits, new accesses to the same partition queue behind its lock request. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. - Increase rotation intervals to reduce partition churn and metadata activity. - Decrease rotation intervals to tighten dead-tuple bounds at the cost of more frequent rotate/prune work. diff --git a/docs/deployment.md b/docs/deployment.md index 48d5c6e47..e0a900404 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -82,7 +82,7 @@ Recommended practice: - monitor `pg_stat_activity` for long transactions - monitor `pg_stat_user_tables` on the active queue-storage schema; ready, tombstone, done, and terminal-delta segments should stay near zero dead tuples, lease segments may spike within the rotation window but should collapse after prune, and `attempt_state` should roughly track live long-running attempts - tune autovacuum for the database if the lease tables churn heavily -- alert on `awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}` (and `error`) sustained above zero: the rings are not recycling. If short readers of the ring partitions are the cause, raise [`prune_lock_timeout`](configuration.md#what-the-knobs-mean) +- alert when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome=~"blocked|error"}[15m])` stays above zero for the alert's `for:` duration: the rings are not recycling. The counter is cumulative, so its raw value stays above zero after a single blocked attempt. If short readers of the ring partitions are the cause, raise [`prune_lock_timeout`](configuration.md#what-the-knobs-mean) Queue-storage depth metrics are designed for high-cadence monitoring. The worker records `available` from lane-head cursor differences and probes queue lag from the next claimable row per lane, instead of running the exact `queue_counts` ready-row scan on every metrics tick. Use the admin API or CLI when you need exact queue counts for an operator action. diff --git a/skills/awa-operations/SKILL.md b/skills/awa-operations/SKILL.md index 17f8ec231..ff6b0eb3d 100644 --- a/skills/awa-operations/SKILL.md +++ b/skills/awa-operations/SKILL.md @@ -294,11 +294,12 @@ The condition to alert on is a frozen generation *with* accumulating rows Ring prune takes exclusive locks under a `lock_timeout` of 10 ms by default; when it cannot, it rolls back and counts `blocked` in -`awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome}`. Persistent -`blocked` (or `error`) means the rings are not recycling. Raise +`awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome}`. A sustained +`increase()` of `blocked` (or `error`) means the rings are not recycling. Raise `ClientBuilder::prune_lock_timeout` (Python `queue_storage_prune_lock_timeout_ms`) in steps when short readers of the ring -partitions are the cause. `backed_off` means prune was skipped for a few ticks +partitions are the cause. Queue-ring prune waits under the timeout only on the +`ready_segments` partition and takes its other partitions with `NOWAIT`. `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`. ## Ring Rotation Cadence From 50b8dddcb1e330ce1db68d28aef6384d0c831c11 Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Fri, 6 Nov 2026 17:44:35 +1300 Subject: [PATCH 4/7] feat(worker): warn when the prune lock timeout reaches deadlock_timeout or statement_timeout --- CHANGELOG.md | 5 +- awa-model/src/queue_storage.rs | 5 +- awa-python/python/awa/client.py | 4 +- awa-worker/src/client.rs | 84 ++++++++++++++++++++++++++++++++- awa-worker/src/storage.rs | 82 ++++++++++++++++++++++++++++++++ docs/configuration.md | 4 +- skills/awa-operations/SKILL.md | 5 +- 7 files changed, 180 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 61476af16..52d65b14b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,7 +15,10 @@ Notable changes between releases. Detailed migration notes for storage transitio `blocked` every tick and the rings stopped recycling. Set it with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` on `client.start()` (Python); the - default stays 10 ms and zero is rejected. `with_prune_lock_timeout` is now + default stays 10 ms and zero or a value above PostgreSQL's `lock_timeout` + maximum is rejected. Start logs a warning when the value is at or above the + connection's `deadlock_timeout` (prune waiting that long can make deadlock + detection cancel a claim instead) or `statement_timeout`. `with_prune_lock_timeout` is now public, with `set_prune_lock_timeout` and `prune_lock_timeout()`. `awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome,awa_ring_reason}` gains `backed_off` (prune skipped by the post-`skipped_active` backoff) and diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index 2e5158ced..b5e57576c 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -3604,7 +3604,10 @@ impl QueueStorage { /// keeps prune from queueing behind readers and so from stalling claims /// and enqueues behind its pending `ACCESS EXCLUSIVE` request. Raise it /// when prune is persistently `Blocked` by short-lived readers of the - /// ring partitions. The timeout is applied at millisecond granularity. + /// ring partitions. Keep it well below `deadlock_timeout` (default 1 s) and + /// any `statement_timeout`: a prune that waits as long as `deadlock_timeout` + /// triggers deadlock detection, which may cancel a concurrent claim instead + /// of the prune. The timeout is applied at millisecond granularity. /// /// Returns a validation error for a zero timeout or one above PostgreSQL's /// `lock_timeout` maximum (`i32::MAX` milliseconds, about 24.8 days). diff --git a/awa-python/python/awa/client.py b/awa-python/python/awa/client.py index 3713c97aa..952ff35d9 100644 --- a/awa-python/python/awa/client.py +++ b/awa-python/python/awa/client.py @@ -972,7 +972,9 @@ async def start( ``lock_timeout`` the maintenance leader uses when pruning the queue, lease and claim rings (default 10 ms). A prune that cannot lock its partitions in time is counted as ``blocked`` and retried on the next - tick; raise it when ``blocked`` outcomes persist. Must be > 0. + tick; raise it when ``blocked`` outcomes persist, keeping it well below the + server's ``deadlock_timeout`` and ``statement_timeout`` (a warning is + logged at start otherwise). Must be > 0. Queue dicts also accept ``claimers`` and ``claim_batch_size`` for hot queue-storage queues. ``claimers`` adds dispatcher/claimer loops that diff --git a/awa-worker/src/client.rs b/awa-worker/src/client.rs index f5c822784..2a96b0303 100644 --- a/awa-worker/src/client.rs +++ b/awa-worker/src/client.rs @@ -32,7 +32,7 @@ use tokio::sync::{Mutex, RwLock}; use tokio::task::JoinSet; use tokio_util::sync::CancellationToken; use tokio_util::task::TaskTracker; -use tracing::{info, warn}; +use tracing::{debug, info, warn}; use uuid::Uuid; /// Errors returned when building a worker client. @@ -994,7 +994,11 @@ impl ClientBuilder { /// `ACCESS EXCLUSIVE` request from stalling claims and enqueues behind it. /// Raise it when `blocked` outcomes persist and the rings stop recycling /// because short-lived readers (admin queries, dashboards) repeatedly hold - /// the ring partitions at the moment prune tries. A zero timeout, or one above + /// the ring partitions at the moment prune tries. Keep it well below + /// PostgreSQL's `deadlock_timeout` (default 1 s), so that a waiting prune + /// is abandoned before deadlock detection can pick a claim as the victim, + /// and below any `statement_timeout`; [`Self::start`] logs a warning when + /// it is not. A zero timeout, or one above /// PostgreSQL's `lock_timeout` maximum (`i32::MAX` ms), makes /// [`Self::build`] fail. Only takes effect when queue storage is active. /// May be set before or after [`Self::queue_storage`]; retained across @@ -1711,6 +1715,37 @@ impl Client { reporter.publish_snapshot().await; } + async fn warn_on_unsafe_prune_lock_timeout(&self) { + let Some(runtime) = self.storage.queue_storage() else { + return; + }; + let timeout = runtime.store.prune_lock_timeout(); + let risks = match crate::storage::check_prune_lock_timeout(&self.pool, timeout).await { + Ok(risks) => risks, + Err(err) => { + debug!(error = %err, "Could not read lock settings to check the prune lock timeout"); + return; + } + }; + for risk in risks { + match risk { + crate::storage::PruneLockTimeoutRisk::DeadlockTimeout { limit_ms } => warn!( + prune_lock_timeout_ms = timeout.as_millis() as u64, + deadlock_timeout_ms = limit_ms, + "Prune lock timeout is at or above deadlock_timeout; a waiting prune can \ + make PostgreSQL run deadlock detection and cancel a concurrent claim. \ + Keep the timeout well below deadlock_timeout" + ), + crate::storage::PruneLockTimeoutRisk::StatementTimeout { limit_ms } => warn!( + prune_lock_timeout_ms = timeout.as_millis() as u64, + statement_timeout_ms = limit_ms, + "Prune lock timeout is at or above statement_timeout; prune is cancelled \ + by the statement timeout and fails instead of reporting blocked" + ), + } + } + } + async fn log_transition_startup_status( &self, effective_storage: &RuntimeStorage, @@ -1784,6 +1819,7 @@ impl Client { self.log_transition_startup_status(&effective_storage) .await?; + self.warn_on_unsafe_prune_lock_timeout().await; admin::sync_queue_descriptors( &self.pool, @@ -3037,6 +3073,50 @@ mod tests { ); } + #[tokio::test] + async fn prune_lock_timeout_check_reads_the_session_limits() { + use crate::storage::{check_prune_lock_timeout, PruneLockTimeoutRisk}; + + let url = database_url(); + ensure_database_exists(&url).await; + let pool = PgPoolOptions::new() + .max_connections(1) + .after_connect(|conn, _meta| { + Box::pin(async move { + sqlx::query("SET deadlock_timeout = '200ms'") + .execute(&mut *conn) + .await?; + sqlx::query("SET statement_timeout = '3s'") + .execute(&mut *conn) + .await?; + Ok(()) + }) + }) + .connect(&url) + .await + .expect("connect with session limits"); + + assert!(check_prune_lock_timeout(&pool, Duration::from_millis(100)) + .await + .unwrap() + .is_empty()); + assert_eq!( + check_prune_lock_timeout(&pool, Duration::from_millis(300)) + .await + .unwrap(), + vec![PruneLockTimeoutRisk::DeadlockTimeout { limit_ms: 200 }] + ); + assert_eq!( + check_prune_lock_timeout(&pool, Duration::from_secs(5)) + .await + .unwrap(), + vec![ + PruneLockTimeoutRisk::DeadlockTimeout { limit_ms: 200 }, + PruneLockTimeoutRisk::StatementTimeout { limit_ms: 3000 }, + ] + ); + } + #[tokio::test] async fn out_of_range_prune_lock_timeout_is_rejected_at_build() { for timeout in [Duration::ZERO, Duration::from_millis(i32::MAX as u64 + 1)] { diff --git a/awa-worker/src/storage.rs b/awa-worker/src/storage.rs index 2a7c51a87..38f52f783 100644 --- a/awa-worker/src/storage.rs +++ b/awa-worker/src/storage.rs @@ -64,3 +64,85 @@ impl RuntimeStorage { self.queue_storage().map(|runtime| runtime.store.clone()) } } + +/// Server settings that a prune `lock_timeout` must stay below. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum PruneLockTimeoutRisk { + /// A prune waiting this long runs PostgreSQL's deadlock detector, which + /// may cancel a concurrent claim or enqueue instead of the prune. + DeadlockTimeout { limit_ms: u64 }, + /// `statement_timeout` cancels the statement first, so the prune fails + /// with an error instead of reporting `blocked`. + StatementTimeout { limit_ms: u64 }, +} + +/// Compare a prune lock timeout with the session's `deadlock_timeout` and +/// `statement_timeout` (milliseconds; a zero `statement_timeout` is disabled). +pub(crate) fn prune_lock_timeout_risks( + timeout: Duration, + deadlock_timeout_ms: Option, + statement_timeout_ms: Option, +) -> Vec { + let timeout_ms = timeout.as_millis(); + let mut risks = Vec::new(); + if let Some(limit_ms) = deadlock_timeout_ms.filter(|limit| *limit > 0) { + if timeout_ms >= u128::from(limit_ms) { + risks.push(PruneLockTimeoutRisk::DeadlockTimeout { limit_ms }); + } + } + if let Some(limit_ms) = statement_timeout_ms.filter(|limit| *limit > 0) { + if timeout_ms >= u128::from(limit_ms) { + risks.push(PruneLockTimeoutRisk::StatementTimeout { limit_ms }); + } + } + risks +} + +/// Read the connection's effective `deadlock_timeout` and `statement_timeout` +/// and report the ones the prune lock timeout reaches. +pub(crate) async fn check_prune_lock_timeout( + pool: &sqlx::PgPool, + timeout: Duration, +) -> Result, sqlx::Error> { + let settings: Vec<(String, i64)> = sqlx::query_as( + "SELECT name, setting::bigint FROM pg_settings \ + WHERE name IN ('deadlock_timeout', 'statement_timeout')", + ) + .fetch_all(pool) + .await?; + let setting = |name: &str| { + settings + .iter() + .find(|(setting_name, _)| setting_name == name) + .and_then(|(_, value)| u64::try_from(*value).ok()) + }; + Ok(prune_lock_timeout_risks( + timeout, + setting("deadlock_timeout"), + setting("statement_timeout"), + )) +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn prune_lock_timeout_risks_flag_timeouts_at_or_above_server_limits() { + let below = Duration::from_millis(999); + let at = Duration::from_millis(1000); + assert!(prune_lock_timeout_risks(below, Some(1000), Some(0)).is_empty()); + assert_eq!( + prune_lock_timeout_risks(at, Some(1000), Some(0)), + vec![PruneLockTimeoutRisk::DeadlockTimeout { limit_ms: 1000 }] + ); + assert_eq!( + prune_lock_timeout_risks(Duration::from_secs(30), Some(1000), Some(5000)), + vec![ + PruneLockTimeoutRisk::DeadlockTimeout { limit_ms: 1000 }, + PruneLockTimeoutRisk::StatementTimeout { limit_ms: 5000 }, + ] + ); + assert!(prune_lock_timeout_risks(Duration::from_secs(30), None, None).is_empty()); + } +} diff --git a/docs/configuration.md b/docs/configuration.md index 68eec547f..929ab887a 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -581,7 +581,7 @@ await client.start( | `queue_rotate_interval` | `1000ms` | How often ready/terminal segments rotate | | `lease_rotate_interval` | `1000ms` | How often lease segments rotate | | `claim_rotate_interval` | matches `queue_rotate_interval` | How often the ADR-023 claim-ring rotates. Set with `ClientBuilder::claim_rotate_interval` (Rust) or `queue_storage_claim_rotate_interval_ms` (Python). Test harnesses sometimes set this to a long interval to pin claim-ring layout for deterministic count assertions. | -| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | +| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero and at most `2147483647` ms; keep it well below `deadlock_timeout` and `statement_timeout`. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | | `ring_rotation_cadence` | 5 s / 2 MiB target / 256 rows / 60 s | A non-empty slot becomes eligible after `min_slot_age` since the first non-empty observation once it holds `min_slot_rows`, when `target_slot_bytes` is reached, or after `max_slot_age` regardless of rows (so a trickle of writes neither seals a nearly empty slot every window nor keeps one open indefinitely). Python: `queue_storage_rotate_min_slot_rows`, `queue_storage_rotate_max_slot_age_ms`. Counts total physical storage, including indexes and TOAST. Empty slots bypass the cadence. The minimum age uses a monotonic clock and resets on an empty observation or leader change; `max_slot_age` also counts from when the slot opened on the database clock, so a leader change does not restart it, except under compat (pre-flip) authority when an older rotator left no ledger row for the slot. `max_slot_age` makes a slot eligible to seal; the busy and reuse checks still decide when it is reclaimed. Configure with `ClientBuilder::ring_rotation_cadence` (Rust) or `queue_storage_rotate_min_slot_age_ms` / `queue_storage_rotate_target_slot_bytes` (Python). A zero byte target disables the size trigger, a zero `min_slot_rows` disables the row floor, and a zero `max_slot_age` disables the ceiling. A row floor needs a size target or a ceiling, and a queue-storage client refuses to build without one, because lease rows are deleted as attempts finish and a lease slot may never reach the floor. A zero `min_slot_age`, or `RingRotationCadence::EAGER`, permits sealing on every tick whatever the other settings. The target is sampled and does not bound retained storage. | The benchmark harness in [postgresql-job-queue-benchmarking](https://github.com/hardbyte/postgresql-job-queue-benchmarking) reads `QUEUE_SLOT_COUNT`, `LEASE_SLOT_COUNT`, `CLAIM_SLOT_COUNT`, `QUEUE_STRIPE_COUNT`, and `LEASE_CLAIM_RECEIPTS` from the environment. Those env vars are benchmark configuration, not general worker-runtime configuration. @@ -596,7 +596,7 @@ Use the defaults unless you have a reason not to: - Increase `lease_slot_count` if lease churn is high enough that dead tuples in the lease ring stop collapsing promptly. - Increase `claim_slot_count` if the rotation cadence (`claim_rotate_interval`) plus the slot count combine to a partition retention window shorter than your longest in-flight zero-deadline short job; running out of empty slots forces `rotate_claims` to return `SkippedBusy` and the receipt-plane churn falls back onto a smaller working set of partitions. - Increase `queue_stripe_count` only for measured workloads where many small replicas contend on the same logical queue. This is queue-storage configuration, not a per-queue `QueueConfig` field: it gives each logical queue the same number of physical stripes. Striping spreads a hot logical queue over `queue#N` physical coordination paths, but it weakens perfect global ordering and can regress calmer shapes if overused. For single hot-queue workloads, benchmark `2` stripes first; higher values should be treated as workload-specific tuning rather than a general default. -- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in steps (for example `100ms`, then `1s`) and keep it well below the time you can tolerate claims and enqueues queueing behind prune; while prune waits, new accesses to the same partition queue behind its lock request. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. +- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in small steps (for example `50ms`, then `100ms`, then `250ms`) and keep it well below PostgreSQL's `deadlock_timeout` (default `1s`) and below any `statement_timeout` on the pool's connections. A prune that waits as long as `deadlock_timeout` makes PostgreSQL run its deadlock detector, and if claims or enqueues are part of a lock cycle with it, the detector can cancel them rather than the prune; a short `lock_timeout` abandons the prune first, so the prune is always the one that gives way. A `statement_timeout` at or below the lock timeout cancels the prune statement before the lock timeout fires, so it fails with an error instead of reporting `blocked`. Startup logs a warning when the configured timeout is at or above either setting. While prune waits, new accesses to the same partition also queue behind its lock request, so a longer timeout trades claim latency for reclamation. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. - Increase rotation intervals to reduce partition churn and metadata activity. - Decrease rotation intervals to tighten dead-tuple bounds at the cost of more frequent rotate/prune work. diff --git a/skills/awa-operations/SKILL.md b/skills/awa-operations/SKILL.md index ff6b0eb3d..8de3047c5 100644 --- a/skills/awa-operations/SKILL.md +++ b/skills/awa-operations/SKILL.md @@ -297,8 +297,9 @@ when it cannot, it rolls back and counts `blocked` in `awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome}`. A sustained `increase()` of `blocked` (or `error`) means the rings are not recycling. Raise `ClientBuilder::prune_lock_timeout` (Python -`queue_storage_prune_lock_timeout_ms`) in steps when short readers of the ring -partitions are the cause. Queue-ring prune waits under the timeout only on the +`queue_storage_prune_lock_timeout_ms`) in small steps (`50ms`, `100ms`, `250ms`) when short readers of the ring +partitions are the cause, and keep it well below `deadlock_timeout` (default 1 s) +and any `statement_timeout`; start logs a warning otherwise. Queue-ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`. `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`. From 2be1f711325ebe4e4657bb2833a5e7fb55014726 Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Fri, 6 Nov 2026 21:01:23 +1300 Subject: [PATCH 5/7] docs(worker): describe prune timeout per lock acquisition --- CHANGELOG.md | 2 ++ awa-model/src/queue_storage.rs | 20 ++++++++++++-------- awa-python/python/awa/client.py | 13 ++++++++----- awa-worker/src/client.rs | 9 +++++---- docs/configuration.md | 4 ++-- skills/awa-operations/SKILL.md | 3 +-- 6 files changed, 30 insertions(+), 21 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 52d65b14b..f5a988b31 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,8 @@ Notable changes between releases. Detailed migration notes for storage transitio `blocked` every tick and the rings stopped recycling. Set it with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` on `client.start()` (Python); the + timeout applies separately to each lock acquisition, not to the whole prune; + queue prune waits only on `ready_segments` and uses `NOWAIT` elsewhere. The default stays 10 ms and zero or a value above PostgreSQL's `lock_timeout` maximum is rejected. Start logs a warning when the value is at or above the connection's `deadlock_timeout` (prune waiting that long can make deadlock diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index b5e57576c..59caffb01 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -3598,15 +3598,19 @@ impl QueueStorage { /// partition locks use `NOWAIT`, so a reader holding one of them makes it /// `Blocked` immediately whatever the timeout. /// - /// A prune that cannot take its locks within the timeout rolls back and - /// reports [`PruneOutcome::Blocked`]; the maintenance loop retries on its - /// next tick. The default is 10 ms, which - /// keeps prune from queueing behind readers and so from stalling claims - /// and enqueues behind its pending `ACCESS EXCLUSIVE` request. Raise it + /// Each lock acquisition gets its own timeout; this does not bound the + /// whole prune. A lock timeout rolls back the prune and reports + /// [`PruneOutcome::Blocked`]; the maintenance loop retries on a later + /// tick. The default is 10 ms, which keeps prune from queueing behind + /// readers and so from stalling claims and enqueues behind its pending + /// `ACCESS EXCLUSIVE` request. Raise it /// when prune is persistently `Blocked` by short-lived readers of the - /// ring partitions. Keep it well below `deadlock_timeout` (default 1 s) and - /// any `statement_timeout`: a prune that waits as long as `deadlock_timeout` - /// triggers deadlock detection, which may cancel a concurrent claim instead + /// ring partitions. Keep it well below `deadlock_timeout` (default 1 s) + /// and + /// any `statement_timeout`: a prune that waits as long as + /// `deadlock_timeout` + /// triggers deadlock detection, which may cancel a concurrent claim + /// instead /// of the prune. The timeout is applied at millisecond granularity. /// /// Returns a validation error for a zero timeout or one above PostgreSQL's diff --git a/awa-python/python/awa/client.py b/awa-python/python/awa/client.py index 952ff35d9..43b13eb68 100644 --- a/awa-python/python/awa/client.py +++ b/awa-python/python/awa/client.py @@ -970,11 +970,14 @@ async def start( ``queue_storage_prune_lock_timeout_ms`` sets the PostgreSQL ``lock_timeout`` the maintenance leader uses when pruning the queue, - lease and claim rings (default 10 ms). A prune that cannot lock its - partitions in time is counted as ``blocked`` and retried on the next - tick; raise it when ``blocked`` outcomes persist, keeping it well below the - server's ``deadlock_timeout`` and ``statement_timeout`` (a warning is - logged at start otherwise). Must be > 0. + lease and claim rings (default 10 ms). Each lock acquisition gets its + own timeout; this does not bound the whole prune. Queue prune waits + only on ``ready_segments``; its other partition locks use ``NOWAIT``. A + lock timeout rolls back the prune and counts it as ``blocked``; the + maintenance loop retries on a later tick. Raise it when ``blocked`` + outcomes persist, keeping it well below the server's + ``deadlock_timeout`` and ``statement_timeout`` (a warning is logged at + start otherwise). Must be > 0. Queue dicts also accept ``claimers`` and ``claim_batch_size`` for hot queue-storage queues. ``claimers`` adds dispatcher/claimer loops that diff --git a/awa-worker/src/client.rs b/awa-worker/src/client.rs index 2a96b0303..c606cc614 100644 --- a/awa-worker/src/client.rs +++ b/awa-worker/src/client.rs @@ -988,10 +988,11 @@ impl ClientBuilder { /// partition locks use `NOWAIT`, so a reader holding one of them makes it /// `blocked` immediately whatever the timeout. /// - /// A prune that cannot take its locks within the timeout rolls back and is - /// recorded as `blocked` in `awa.maintenance.prune.attempts`; it retries on - /// the next maintenance tick. The short default keeps the pending - /// `ACCESS EXCLUSIVE` request from stalling claims and enqueues behind it. + /// Each lock acquisition gets its own timeout; this does not bound the + /// whole prune. A lock timeout rolls back the prune and records `blocked` + /// in `awa.maintenance.prune.attempts`; the maintenance loop retries on a + /// later tick. The short default keeps the pending `ACCESS EXCLUSIVE` + /// request from stalling claims and enqueues behind it. /// Raise it when `blocked` outcomes persist and the rings stop recycling /// because short-lived readers (admin queries, dashboards) repeatedly hold /// the ring partitions at the moment prune tries. Keep it well below diff --git a/docs/configuration.md b/docs/configuration.md index 929ab887a..66f9fb3e6 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -581,7 +581,7 @@ await client.start( | `queue_rotate_interval` | `1000ms` | How often ready/terminal segments rotate | | `lease_rotate_interval` | `1000ms` | How often lease segments rotate | | `claim_rotate_interval` | matches `queue_rotate_interval` | How often the ADR-023 claim-ring rotates. Set with `ClientBuilder::claim_rotate_interval` (Rust) or `queue_storage_claim_rotate_interval_ms` (Python). Test harnesses sometimes set this to a long interval to pin claim-ring layout for deterministic count assertions. | -| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. A prune that cannot lock its partitions within the timeout rolls back, is counted as `blocked`, and is retried on the next maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero and at most `2147483647` ms; keep it well below `deadlock_timeout` and `statement_timeout`. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | +| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. The timeout applies separately to each lock acquisition, not to the whole prune. A lock timeout rolls the prune back, is counted as `blocked`, and is retried on a later maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero and at most `2147483647` ms; keep it well below `deadlock_timeout` and `statement_timeout`. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | | `ring_rotation_cadence` | 5 s / 2 MiB target / 256 rows / 60 s | A non-empty slot becomes eligible after `min_slot_age` since the first non-empty observation once it holds `min_slot_rows`, when `target_slot_bytes` is reached, or after `max_slot_age` regardless of rows (so a trickle of writes neither seals a nearly empty slot every window nor keeps one open indefinitely). Python: `queue_storage_rotate_min_slot_rows`, `queue_storage_rotate_max_slot_age_ms`. Counts total physical storage, including indexes and TOAST. Empty slots bypass the cadence. The minimum age uses a monotonic clock and resets on an empty observation or leader change; `max_slot_age` also counts from when the slot opened on the database clock, so a leader change does not restart it, except under compat (pre-flip) authority when an older rotator left no ledger row for the slot. `max_slot_age` makes a slot eligible to seal; the busy and reuse checks still decide when it is reclaimed. Configure with `ClientBuilder::ring_rotation_cadence` (Rust) or `queue_storage_rotate_min_slot_age_ms` / `queue_storage_rotate_target_slot_bytes` (Python). A zero byte target disables the size trigger, a zero `min_slot_rows` disables the row floor, and a zero `max_slot_age` disables the ceiling. A row floor needs a size target or a ceiling, and a queue-storage client refuses to build without one, because lease rows are deleted as attempts finish and a lease slot may never reach the floor. A zero `min_slot_age`, or `RingRotationCadence::EAGER`, permits sealing on every tick whatever the other settings. The target is sampled and does not bound retained storage. | The benchmark harness in [postgresql-job-queue-benchmarking](https://github.com/hardbyte/postgresql-job-queue-benchmarking) reads `QUEUE_SLOT_COUNT`, `LEASE_SLOT_COUNT`, `CLAIM_SLOT_COUNT`, `QUEUE_STRIPE_COUNT`, and `LEASE_CLAIM_RECEIPTS` from the environment. Those env vars are benchmark configuration, not general worker-runtime configuration. @@ -596,7 +596,7 @@ Use the defaults unless you have a reason not to: - Increase `lease_slot_count` if lease churn is high enough that dead tuples in the lease ring stop collapsing promptly. - Increase `claim_slot_count` if the rotation cadence (`claim_rotate_interval`) plus the slot count combine to a partition retention window shorter than your longest in-flight zero-deadline short job; running out of empty slots forces `rotate_claims` to return `SkippedBusy` and the receipt-plane churn falls back onto a smaller working set of partitions. - Increase `queue_stripe_count` only for measured workloads where many small replicas contend on the same logical queue. This is queue-storage configuration, not a per-queue `QueueConfig` field: it gives each logical queue the same number of physical stripes. Striping spreads a hot logical queue over `queue#N` physical coordination paths, but it weakens perfect global ordering and can regress calmer shapes if overused. For single hot-queue workloads, benchmark `2` stripes first; higher values should be treated as workload-specific tuning rather than a general default. -- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in small steps (for example `50ms`, then `100ms`, then `250ms`) and keep it well below PostgreSQL's `deadlock_timeout` (default `1s`) and below any `statement_timeout` on the pool's connections. A prune that waits as long as `deadlock_timeout` makes PostgreSQL run its deadlock detector, and if claims or enqueues are part of a lock cycle with it, the detector can cancel them rather than the prune; a short `lock_timeout` abandons the prune first, so the prune is always the one that gives way. A `statement_timeout` at or below the lock timeout cancels the prune statement before the lock timeout fires, so it fails with an error instead of reporting `blocked`. Startup logs a warning when the configured timeout is at or above either setting. While prune waits, new accesses to the same partition also queue behind its lock request, so a longer timeout trades claim latency for reclamation. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. +- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in small steps (for example `50ms`, then `100ms`, then `250ms`) and keep it well below PostgreSQL's `deadlock_timeout` (default `1s`) and below any `statement_timeout` on the pool's connections. A single lock wait that reaches `deadlock_timeout` makes PostgreSQL run its deadlock detector, and if claims or enqueues are part of a lock cycle with it, the detector can cancel them rather than the prune; a short `lock_timeout` abandons the prune first, so the prune is always the one that gives way. A `statement_timeout` at or below the lock timeout cancels the prune statement before the lock timeout fires, so it fails with an error instead of reporting `blocked`. Startup logs a warning when the configured timeout is at or above either setting. While prune waits, new accesses to the same partition also queue behind its lock request, so a longer timeout trades claim latency for reclamation. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. - Increase rotation intervals to reduce partition churn and metadata activity. - Decrease rotation intervals to tighten dead-tuple bounds at the cost of more frequent rotate/prune work. diff --git a/skills/awa-operations/SKILL.md b/skills/awa-operations/SKILL.md index 8de3047c5..6ee89a4a6 100644 --- a/skills/awa-operations/SKILL.md +++ b/skills/awa-operations/SKILL.md @@ -292,8 +292,7 @@ The condition to alert on is a frozen generation *with* accumulating rows ## Prune Lock Timeout -Ring prune takes exclusive locks under a `lock_timeout` of 10 ms by default; -when it cannot, it rolls back and counts `blocked` in +Ring prune gives each lock acquisition its own `lock_timeout` of 10 ms by default; this does not bound the whole prune. A lock timeout rolls it back and counts `blocked` in `awa_maintenance_prune_attempts_total{awa_ring,awa_ring_outcome}`. A sustained `increase()` of `blocked` (or `error`) means the rings are not recycling. Raise `ClientBuilder::prune_lock_timeout` (Python From 986a7d15361daed8f49b2718def49099bc280066 Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Sat, 7 Nov 2026 02:33:30 +1300 Subject: [PATCH 6/7] Exclude tombstoned ready rows from point reads Apply the reviewed standalone read fix to the prune-timeout branch. Match the full physical tombstone identity and cover priority and queue moves across ready-ring wrap with deterministic regressions. --- CHANGELOG.md | 5 ++ awa-model/src/queue_storage.rs | 13 ++- awa/tests/queue_storage_runtime_test.rs | 111 ++++++++++++++++++++++++ 3 files changed, 127 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index f5a988b31..0854a18d3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -30,6 +30,11 @@ Notable changes between releases. Detailed migration notes for storage transitio ### Fixed +- **Point reads show the live queue and priority after a lane move.** Retained + ready rows from before a priority or queue change could win a read's tie + after the ring wrapped, returning the old fields even though the batch + operation succeeded. Point reads now exclude tombstoned source rows. + - **Batch enqueues take their lane locks in one order, so they no longer deadlock with each other.** On queue storage every enqueue holds a transaction-scoped advisory lock on its `(queue, priority, shard)` lane diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index 59caffb01..fad11a694 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -14309,8 +14309,17 @@ impl QueueStorage { unique_key, unique_states, COALESCE(payload, '{{}}'::jsonb) AS payload - FROM {schema}.ready_entries - WHERE job_id = $1 + FROM {schema}.ready_entries AS ready + WHERE ready.job_id = $1 + AND NOT EXISTS ( + SELECT 1 FROM {schema}.ready_tombstones AS tomb + WHERE tomb.ready_slot = ready.ready_slot + AND tomb.ready_generation = ready.ready_generation + AND tomb.queue = ready.queue + AND tomb.priority = ready.priority + AND tomb.enqueue_shard = ready.enqueue_shard + AND tomb.lane_seq = ready.lane_seq + ) ORDER BY run_lease DESC, attempted_at DESC NULLS LAST, run_at DESC "#, ))) diff --git a/awa/tests/queue_storage_runtime_test.rs b/awa/tests/queue_storage_runtime_test.rs index 9f106bd92..9bf5c8468 100644 --- a/awa/tests/queue_storage_runtime_test.rs +++ b/awa/tests/queue_storage_runtime_test.rs @@ -21431,3 +21431,114 @@ async fn test_queue_storage_legacy_row_claims_are_locked_before_the_heartbeat_st .expect("join heartbeat") .expect("heartbeat after the rewrite"); } + +/// A lane move leaves immutable source rows behind. Wrap the ring so the +/// destination is in an earlier partition: point reads must use live evidence, +/// rather than depending on which equal-timestamp ready row the plan emits last. +async fn ready_point_read_wrap_fixture() -> (TestDbGuard, sqlx::PgPool, QueueStorage, i64) { + let (guard, pool) = setup_pool(4).await; + let store = create_store_with_config( + &pool, + QueueStorageConfig { + schema: "awa_qs_point_read_wrap".to_string(), + queue_slot_count: 4, + lease_slot_count: 2, + claim_slot_count: 2, + ..Default::default() + }, + ) + .await; + // A fresh empty ring can be positioned just before wrap without retaining + // unrelated jobs. This is the state reached after three rotations/prunes. + let schema = store.schema(); + sqlx::query(audited_sql(format!( + "INSERT INTO {schema}.queue_ring_rotations (generation, slot) VALUES (3, 3)" + ))) + .execute(&pool) + .await + .expect("position empty ring before wrap"); + sqlx::query(audited_sql(format!( + "UPDATE {schema}.queue_ring_slots SET generation = 3 WHERE slot = 3" + ))) + .execute(&pool) + .await + .expect("set current slot generation"); + let job_id = enqueue_job( + &pool, + &store, + &CompleteJob { id: 1 }, + InsertOpts { + queue: "point_read_source".to_string(), + priority: 4, + ..Default::default() + }, + ) + .await; + assert!(matches!( + store.rotate(&pool).await.expect("wrap to slot zero"), + RotateOutcome::Rotated { slot: 0, .. } + )); + (guard, pool, store, job_id) +} + +async fn assert_live_ready_row( + pool: &sqlx::PgPool, + store: &QueueStorage, + job_id: i64, + expected_queue: &str, + expected_priority: i16, +) { + let schema = store.schema(); + let live: Vec<(String, i16, i32)> = sqlx::query_as(audited_sql(format!( + "SELECT ready.queue, ready.priority, ready.ready_slot + FROM {schema}.ready_entries AS ready + WHERE ready.job_id = $1 + AND NOT EXISTS ( + SELECT 1 FROM {schema}.ready_tombstones AS tomb + WHERE tomb.ready_slot = ready.ready_slot + AND tomb.ready_generation = ready.ready_generation + AND tomb.queue = ready.queue + AND tomb.priority = ready.priority + AND tomb.enqueue_shard = ready.enqueue_shard + AND tomb.lane_seq = ready.lane_seq + )" + ))) + .bind(job_id) + .fetch_all(pool) + .await + .expect("read live ready evidence"); + assert_eq!( + live, + vec![(expected_queue.to_string(), expected_priority, 0)] + ); +} + +#[tokio::test] +async fn test_point_read_uses_live_ready_priority_after_ring_wrap() { + let (_guard, pool, store, job_id) = ready_point_read_wrap_fixture().await; + assert!(store + .set_priority(&pool, job_id, 1) + .await + .expect("set priority")); + assert_live_ready_row(&pool, &store, job_id, "point_read_source", 1).await; + let job = admin::get_job(&pool, job_id).await.expect("read moved job"); + assert_eq!( + job.priority, 1, + "point read must ignore the tombstoned source" + ); +} + +#[tokio::test] +async fn test_point_read_uses_live_ready_queue_after_ring_wrap() { + let (_guard, pool, store, job_id) = ready_point_read_wrap_fixture().await; + assert!(store + .move_queue(&pool, job_id, "point_read_destination", None) + .await + .expect("move queue")); + assert_live_ready_row(&pool, &store, job_id, "point_read_destination", 4).await; + let job = admin::get_job(&pool, job_id).await.expect("read moved job"); + assert_eq!( + job.queue, "point_read_destination", + "point read must ignore the tombstoned source" + ); +} From 0d74275166c1e051f104e4e6ebefb5be4d54cd0a Mon Sep 17 00:00:00 2001 From: Brian Thorne Date: Sat, 7 Nov 2026 04:23:22 +1300 Subject: [PATCH 7/7] fix(storage): roll back prune on later lock timeouts --- CHANGELOG.md | 9 +- awa-model/src/queue_storage.rs | 1398 +++++++++++------------ awa-python/python/awa/client.py | 7 +- awa/tests/queue_storage_runtime_test.rs | 175 +++ docs/configuration.md | 4 +- 5 files changed, 876 insertions(+), 717 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0854a18d3..b1ca9d960 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -16,7 +16,8 @@ Notable changes between releases. Detailed migration notes for storage transitio `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` on `client.start()` (Python); the timeout applies separately to each lock acquisition, not to the whole prune; - queue prune waits only on `ready_segments` and uses `NOWAIT` elsewhere. The + queue prune takes its other initial partition locks with `NOWAIT`. Later + statements also run under the timeout. The default stays 10 ms and zero or a value above PostgreSQL's `lock_timeout` maximum is rejected. Start logs a warning when the value is at or above the connection's `deadlock_timeout` (prune waiting that long can make deadlock @@ -30,6 +31,12 @@ Notable changes between releases. Detailed migration notes for storage transitio ### Fixed +- **Prune and terminal-count rollup roll back and report `Blocked` when a + later statement times out on a lock.** The timeout also covers failed-row + carry, terminal-count updates and post-lock liveness checks. Those waits + previously escaped as `55P03` errors after the initial partition locks had + succeeded. The whole attempt now rolls back before maintenance retries; + rollup stops at its first blocked slot. - **Point reads show the live queue and priority after a lane move.** Retained ready rows from before a priority or queue change could win a read's tie after the ring wrapped, returning the old fields even though the batch diff --git a/awa-model/src/queue_storage.rs b/awa-model/src/queue_storage.rs index fad11a694..574d7082a 100644 --- a/awa-model/src/queue_storage.rs +++ b/awa-model/src/queue_storage.rs @@ -713,6 +713,35 @@ async fn set_prune_lock_timeout_tx( Ok(()) } +/// Commit or roll back a maintenance transaction that has set the prune +/// `lock_timeout`. +/// +/// The timeout applies to every later statement in the transaction, not only +/// the explicit `LOCK TABLE`: an insert, update or read of another relation can +/// also queue behind a conflicting lock (autovacuum's heap truncation takes +/// `ACCESS EXCLUSIVE`, for example). A lock timeout anywhere therefore rolls the +/// whole transaction back and reports `blocked`, so the caller backs off and +/// retries instead of surfacing an error. +async fn settle_prune_tx( + tx: sqlx::Transaction<'_, Postgres>, + result: Result, + blocked: T, +) -> Result { + match result { + Ok(outcome) => { + tx.commit().await.map_err(map_sqlx_error)?; + Ok(outcome) + } + Err(err) => { + let _ = tx.rollback().await; + match err { + AwaError::Database(ref db_err) if is_lock_contention_error(db_err) => Ok(blocked), + err => Err(err), + } + } + } +} + fn validate_ident(ident: &str) -> Result<(), AwaError> { let mut chars = ident.chars(); match chars.next() { @@ -3591,12 +3620,13 @@ impl QueueStorage { } } - /// Set the PostgreSQL `lock_timeout` applied to the exclusive-lock steps of + /// Set the PostgreSQL `lock_timeout` applied to the lock acquisitions of /// ring prune (queue, lease and claim rings) and terminal-delta rollup. /// - /// Queue ring prune waits only on its `ready_segments` lock; its other - /// partition locks use `NOWAIT`, so a reader holding one of them makes it - /// `Blocked` immediately whatever the timeout. + /// Among its initial partition locks, queue ring prune waits only on + /// `ready_segments`; the others use `NOWAIT`. Later reads and writes also + /// run under the timeout. A reader holding a `NOWAIT` partition makes the + /// prune `Blocked` immediately whatever the timeout. /// /// Each lock acquisition gets its own timeout; this does not bound the /// whole prune. A lock timeout rolls back the prune and reports @@ -3637,7 +3667,7 @@ impl QueueStorage { Ok(()) } - /// The `lock_timeout` applied to prune's exclusive-lock steps. + /// The `lock_timeout` applied to prune's lock acquisitions. pub fn prune_lock_timeout(&self) -> Duration { self.prune_lock_timeout } @@ -18212,7 +18242,10 @@ impl QueueStorage { break; } TerminalDeltaSlotRollup::Blocked => { + // The next slot would most likely wait out the same lock + // timeout, and the leader loop is blocked while it does. outcome.blocked_slots += 1; + break; } } } @@ -18399,237 +18432,215 @@ impl QueueStorage { return Ok(TerminalDeltaSlotRollup::SkippedActive); } - set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - - let lock_delta = sqlx::query(audited_sql(format!( - "LOCK TABLE {delta_child} IN ACCESS EXCLUSIVE MODE" - ))) - .execute(tx.as_mut()) - .await; + let locked: Result = async { + set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - match lock_delta { - Ok(_) => {} - Err(err) if is_lock_contention_error(&err) => { - let _ = tx.rollback().await; - return Ok(TerminalDeltaSlotRollup::Blocked); - } - Err(err) => { - let _ = tx.rollback().await; - return Err(map_sqlx_error(err)); - } - } - - let active_leases = - queue_prune_has_active_leases_tx(&mut tx, schema, slot, generation).await?; - - if active_leases { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(TerminalDeltaSlotRollup::SkippedActive); - } + sqlx::query(audited_sql(format!( + "LOCK TABLE {delta_child} IN ACCESS EXCLUSIVE MODE" + ))) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; - let unclosed_claim_refs = - queue_prune_has_unclosed_claim_refs_tx(&mut tx, schema, slot, generation).await?; + let active_leases = + queue_prune_has_active_leases_tx(&mut tx, schema, slot, generation).await?; - if unclosed_claim_refs { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(TerminalDeltaSlotRollup::SkippedActive); - } + if active_leases { + return Ok(TerminalDeltaSlotRollup::SkippedActive); + } - let delta_rows: i64 = sqlx::query_scalar(audited_sql(format!( - r#" - SELECT count(*)::bigint - FROM {delta_child} - WHERE ready_generation = $1 - "# - ))) - .bind(generation) - .fetch_one(tx.as_mut()) - .await - .map_err(map_sqlx_error)?; + let unclosed_claim_refs = + queue_prune_has_unclosed_claim_refs_tx(&mut tx, schema, slot, generation).await?; - if delta_rows == 0 { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(TerminalDeltaSlotRollup::Empty); - } + if unclosed_claim_refs { + return Ok(TerminalDeltaSlotRollup::SkippedActive); + } - // In ledger authority each touched lane collapses to one bucket-0 row - // holding its old total (summed over every bucket) plus the signed - // delta, which keeps a negative delta exact when the matching positive - // count sits in another bucket. Before the flip, N-1 maintenance can - // still win the election and folds per job-id bucket, so the fold - // keeps that shape until the flip fences it (ADR-041). - let grouped_keys: i64 = match authority { - RingAuthority::Ledger => sqlx::query_scalar(audited_sql(format!( + let delta_rows: i64 = sqlx::query_scalar(audited_sql(format!( r#" - WITH grouped AS MATERIALIZED ( - SELECT - ready_slot, - queue, - priority, - enqueue_shard, - SUM(terminal_delta)::bigint AS delta + SELECT count(*)::bigint FROM {delta_child} WHERE ready_generation = $1 - GROUP BY ready_slot, queue, priority, enqueue_shard - HAVING SUM(terminal_delta) <> 0 - ), - collapsed AS ( - DELETE FROM {schema}.queue_terminal_live_counts AS counts - USING grouped - WHERE counts.ready_slot = grouped.ready_slot - AND counts.queue = grouped.queue - AND counts.priority = grouped.priority - AND counts.enqueue_shard = grouped.enqueue_shard - RETURNING - counts.ready_slot, - counts.queue, - counts.priority, - counts.enqueue_shard, - counts.live_terminal_count - ), - folded AS ( - SELECT - grouped.ready_slot, - grouped.queue, - grouped.priority, - grouped.enqueue_shard, - (grouped.delta + COALESCE(SUM(collapsed.live_terminal_count), 0))::bigint - AS live_terminal_count - FROM grouped - LEFT JOIN collapsed - ON collapsed.ready_slot = grouped.ready_slot - AND collapsed.queue = grouped.queue - AND collapsed.priority = grouped.priority - AND collapsed.enqueue_shard = grouped.enqueue_shard - GROUP BY - grouped.ready_slot, - grouped.queue, - grouped.priority, - grouped.enqueue_shard, - grouped.delta - ), - inserted AS ( - INSERT INTO {schema}.queue_terminal_live_counts ( - ready_slot, - queue, - priority, - enqueue_shard, - counter_bucket, - live_terminal_count - ) - SELECT - ready_slot, - queue, - priority, - enqueue_shard, - 0::smallint, - live_terminal_count - FROM folded - WHERE live_terminal_count <> 0 - ORDER BY ready_slot, queue, priority, enqueue_shard - RETURNING 1 - ) - SELECT count(*)::bigint FROM grouped - "# - ))) - .bind(generation) - .fetch_one(tx.as_mut()) - .await - .map_err(map_sqlx_error)?, - RingAuthority::Columns => sqlx::query_scalar(audited_sql(format!( - r#" - WITH grouped AS MATERIALIZED ( - SELECT - ready_slot, - queue, - priority, - enqueue_shard, - counter_bucket, - SUM(terminal_delta)::bigint AS delta - FROM {delta_child} - WHERE ready_generation = $1 - GROUP BY ready_slot, queue, priority, enqueue_shard, counter_bucket - HAVING SUM(terminal_delta) <> 0 - ), - updated AS ( - UPDATE {schema}.queue_terminal_live_counts AS counts - SET live_terminal_count = GREATEST(0, counts.live_terminal_count + grouped.delta) - FROM grouped - WHERE counts.ready_slot = grouped.ready_slot - AND counts.queue = grouped.queue - AND counts.priority = grouped.priority - AND counts.enqueue_shard = grouped.enqueue_shard - AND counts.counter_bucket = grouped.counter_bucket - RETURNING - counts.ready_slot, - counts.queue, - counts.priority, - counts.enqueue_shard, - counts.counter_bucket - ), - inserted AS ( - INSERT INTO {schema}.queue_terminal_live_counts AS counts ( - ready_slot, - queue, - priority, - enqueue_shard, - counter_bucket, - live_terminal_count - ) - SELECT - grouped.ready_slot, - grouped.queue, - grouped.priority, - grouped.enqueue_shard, - grouped.counter_bucket, - grouped.delta - FROM grouped - WHERE grouped.delta > 0 - AND NOT EXISTS ( - SELECT 1 - FROM updated - WHERE updated.ready_slot = grouped.ready_slot - AND updated.queue = grouped.queue - AND updated.priority = grouped.priority - AND updated.enqueue_shard = grouped.enqueue_shard - AND updated.counter_bucket = grouped.counter_bucket - ) - ORDER BY ready_slot, queue, priority, enqueue_shard, counter_bucket - ON CONFLICT (ready_slot, queue, priority, enqueue_shard, counter_bucket) DO UPDATE - SET live_terminal_count = - GREATEST(0, counts.live_terminal_count + EXCLUDED.live_terminal_count) - RETURNING 1 - ) - SELECT count(*)::bigint FROM grouped - "# + "# ))) .bind(generation) .fetch_one(tx.as_mut()) .await - .map_err(map_sqlx_error)?, - }; - - let truncate_delta = sqlx::query(audited_sql(format!("TRUNCATE TABLE {delta_child}"))) - .execute(tx.as_mut()) - .await; + .map_err(map_sqlx_error)?; - match truncate_delta { - Ok(_) => { - tx.commit().await.map_err(map_sqlx_error)?; - Ok(TerminalDeltaSlotRollup::Rolled { - delta_rows, - grouped_keys, - }) - } - Err(err) if is_lock_contention_error(&err) => { - let _ = tx.rollback().await; - Ok(TerminalDeltaSlotRollup::Blocked) - } - Err(err) => { - let _ = tx.rollback().await; - Err(map_sqlx_error(err)) + if delta_rows == 0 { + return Ok(TerminalDeltaSlotRollup::Empty); } + + // In ledger authority each touched lane collapses to one bucket-0 row + // holding its old total (summed over every bucket) plus the signed + // delta, which keeps a negative delta exact when the matching positive + // count sits in another bucket. Before the flip, N-1 maintenance can + // still win the election and folds per job-id bucket, so the fold + // keeps that shape until the flip fences it (ADR-041). + let grouped_keys: i64 = match authority { + RingAuthority::Ledger => sqlx::query_scalar(audited_sql(format!( + r#" + WITH grouped AS MATERIALIZED ( + SELECT + ready_slot, + queue, + priority, + enqueue_shard, + SUM(terminal_delta)::bigint AS delta + FROM {delta_child} + WHERE ready_generation = $1 + GROUP BY ready_slot, queue, priority, enqueue_shard + HAVING SUM(terminal_delta) <> 0 + ), + collapsed AS ( + DELETE FROM {schema}.queue_terminal_live_counts AS counts + USING grouped + WHERE counts.ready_slot = grouped.ready_slot + AND counts.queue = grouped.queue + AND counts.priority = grouped.priority + AND counts.enqueue_shard = grouped.enqueue_shard + RETURNING + counts.ready_slot, + counts.queue, + counts.priority, + counts.enqueue_shard, + counts.live_terminal_count + ), + folded AS ( + SELECT + grouped.ready_slot, + grouped.queue, + grouped.priority, + grouped.enqueue_shard, + (grouped.delta + COALESCE(SUM(collapsed.live_terminal_count), 0))::bigint + AS live_terminal_count + FROM grouped + LEFT JOIN collapsed + ON collapsed.ready_slot = grouped.ready_slot + AND collapsed.queue = grouped.queue + AND collapsed.priority = grouped.priority + AND collapsed.enqueue_shard = grouped.enqueue_shard + GROUP BY + grouped.ready_slot, + grouped.queue, + grouped.priority, + grouped.enqueue_shard, + grouped.delta + ), + inserted AS ( + INSERT INTO {schema}.queue_terminal_live_counts ( + ready_slot, + queue, + priority, + enqueue_shard, + counter_bucket, + live_terminal_count + ) + SELECT + ready_slot, + queue, + priority, + enqueue_shard, + 0::smallint, + live_terminal_count + FROM folded + WHERE live_terminal_count <> 0 + ORDER BY ready_slot, queue, priority, enqueue_shard + RETURNING 1 + ) + SELECT count(*)::bigint FROM grouped + "# + ))) + .bind(generation) + .fetch_one(tx.as_mut()) + .await + .map_err(map_sqlx_error)?, + RingAuthority::Columns => sqlx::query_scalar(audited_sql(format!( + r#" + WITH grouped AS MATERIALIZED ( + SELECT + ready_slot, + queue, + priority, + enqueue_shard, + counter_bucket, + SUM(terminal_delta)::bigint AS delta + FROM {delta_child} + WHERE ready_generation = $1 + GROUP BY ready_slot, queue, priority, enqueue_shard, counter_bucket + HAVING SUM(terminal_delta) <> 0 + ), + updated AS ( + UPDATE {schema}.queue_terminal_live_counts AS counts + SET live_terminal_count = GREATEST(0, counts.live_terminal_count + grouped.delta) + FROM grouped + WHERE counts.ready_slot = grouped.ready_slot + AND counts.queue = grouped.queue + AND counts.priority = grouped.priority + AND counts.enqueue_shard = grouped.enqueue_shard + AND counts.counter_bucket = grouped.counter_bucket + RETURNING + counts.ready_slot, + counts.queue, + counts.priority, + counts.enqueue_shard, + counts.counter_bucket + ), + inserted AS ( + INSERT INTO {schema}.queue_terminal_live_counts AS counts ( + ready_slot, + queue, + priority, + enqueue_shard, + counter_bucket, + live_terminal_count + ) + SELECT + grouped.ready_slot, + grouped.queue, + grouped.priority, + grouped.enqueue_shard, + grouped.counter_bucket, + grouped.delta + FROM grouped + WHERE grouped.delta > 0 + AND NOT EXISTS ( + SELECT 1 + FROM updated + WHERE updated.ready_slot = grouped.ready_slot + AND updated.queue = grouped.queue + AND updated.priority = grouped.priority + AND updated.enqueue_shard = grouped.enqueue_shard + AND updated.counter_bucket = grouped.counter_bucket + ) + ORDER BY ready_slot, queue, priority, enqueue_shard, counter_bucket + ON CONFLICT (ready_slot, queue, priority, enqueue_shard, counter_bucket) DO UPDATE + SET live_terminal_count = + GREATEST(0, counts.live_terminal_count + EXCLUDED.live_terminal_count) + RETURNING 1 + ) + SELECT count(*)::bigint FROM grouped + "# + ))) + .bind(generation) + .fetch_one(tx.as_mut()) + .await + .map_err(map_sqlx_error)?, + }; + + sqlx::query(audited_sql(format!("TRUNCATE TABLE {delta_child}"))) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + Ok(TerminalDeltaSlotRollup::Rolled { + delta_rows, + grouped_keys, + }) } + .await; + + settle_prune_tx(tx, locked, TerminalDeltaSlotRollup::Blocked).await } /// Fold pending `queue_terminal_rollup_deltas` rows into the @@ -18879,172 +18890,119 @@ impl QueueStorage { }); } - set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; + let locked: Result = async { + set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - let lock_started = Instant::now(); - // Claims read segments before ready rows, while producers write in - // the opposite order. Queue behind segment readers, then abandon - // the transaction rather than wait with an exclusive child held. - let lock_tables = async { - sqlx::query(audited_sql(format!( - "LOCK TABLE {segment_child} IN ACCESS EXCLUSIVE MODE" - ))) - .execute(tx.as_mut()) - .await?; - sqlx::query(audited_sql(format!( - "LOCK TABLE {ready_child}, {claim_attempt_child}, {done_child}, {tomb_child}, {receipt_batch_child}, {receipt_tomb_child}, {delta_child} IN ACCESS EXCLUSIVE MODE NOWAIT" - ))) - .execute(tx.as_mut()) + let lock_started = Instant::now(); + // Claims read segments before ready rows, while producers write in + // the opposite order. Queue behind segment readers, then abandon + // the transaction rather than wait with an exclusive child held. + async { + sqlx::query(audited_sql(format!( + "LOCK TABLE {segment_child} IN ACCESS EXCLUSIVE MODE" + ))) + .execute(tx.as_mut()) + .await?; + sqlx::query(audited_sql(format!( + "LOCK TABLE {ready_child}, {claim_attempt_child}, {done_child}, {tomb_child}, {receipt_batch_child}, {receipt_tomb_child}, {delta_child} IN ACCESS EXCLUSIVE MODE NOWAIT" + ))) + .execute(tx.as_mut()) + .await + } .await - } - .await; - let lock_duration = lock_started.elapsed(); - - if let Err(err) = lock_tables { - let _ = tx.rollback().await; - if is_lock_contention_error(&err) { - return Ok(PruneOutcome::Blocked { slot }); + .map_err(map_sqlx_error)?; + let lock_duration = lock_started.elapsed(); + + // The pre-lock gates are only an MVCC snapshot. If an in-flight + // producer or claimer committed while the exclusive partition + // lock waited, these post-lock gates see it before TRUNCATE. + let active_leases = + queue_prune_has_active_leases_tx(&mut tx, schema, slot, generation).await?; + if active_leases { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::QueueActiveLeases, + count: busy_indicator(active_leases), + }); } - return Err(map_sqlx_error(err)); - } - // The pre-lock gates are only an MVCC snapshot. If an in-flight - // producer or claimer committed while the exclusive partition - // lock waited, these post-lock gates see it before TRUNCATE. - let active_leases = - queue_prune_has_active_leases_tx(&mut tx, schema, slot, generation).await?; - if active_leases { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::QueueActiveLeases, - count: busy_indicator(active_leases), - }); - } - - let pending = queue_prune_has_pending_ready_tx(&mut tx, schema, slot, generation).await?; - if pending { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::QueuePendingReady, - count: busy_indicator(pending), - }); - } + let pending = queue_prune_has_pending_ready_tx(&mut tx, schema, slot, generation).await?; + if pending { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::QueuePendingReady, + count: busy_indicator(pending), + }); + } - let unclosed_claim_refs = - queue_prune_has_unclosed_claim_refs_tx(&mut tx, schema, slot, generation).await?; - if unclosed_claim_refs { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::QueueUnclosedClaimRefs, - count: busy_indicator(unclosed_claim_refs), - }); - } + let unclosed_claim_refs = + queue_prune_has_unclosed_claim_refs_tx(&mut tx, schema, slot, generation).await?; + if unclosed_claim_refs { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::QueueUnclosedClaimRefs, + count: busy_indicator(unclosed_claim_refs), + }); + } - let failed_retention_secs = i64::try_from(failed_retention.as_secs()).unwrap_or(i64::MAX); - let retention_floor = failed_retention_secs > 0; - - // #337: failed terminal rows still inside the retention floor - // are re-homed into the live done segment before the TRUNCATE - // so they stay retryable. The ring rotation lock is held above, - // which serializes against rotate — the current slot (and its - // generation, read from the ledger cursor) cannot move while - // carried rows are re-inserted into it. - let carried_failed_rows = if retention_floor { - // Carried rows are widened to the self-contained synthetic - // done-row shape (the COALESCE chain mirrors - // `done_row_projection`) because the ready rows they would - // otherwise hydrate from are truncated with this slot. - // Deliberately no ON CONFLICT: lane_seq comes from - // never-resetting sequences, so a PK collision means - // corrupted terminal state and must abort the prune loudly - // rather than silently drop a terminal fact. - let carried = sqlx::query(audited_sql(format!( - r#" - INSERT INTO {schema}.done_entries ( - ready_slot, ready_generation, job_id, kind, queue, - args, state, priority, attempt, run_lease, - max_attempts, lane_seq, enqueue_shard, run_at, - attempted_at, finalized_at, created_at, unique_key, - unique_states, payload - ) - SELECT - $2, - $3, - done.job_id, - done.kind, - done.queue, - COALESCE(done.args, ready.args, '{{}}'::jsonb), - done.state, - done.priority, - done.attempt, - done.run_lease, - COALESCE(done.max_attempts, ready.max_attempts, 25::smallint), - done.lane_seq, - done.enqueue_shard, - COALESCE(done.run_at, ready.run_at, done.finalized_at), - COALESCE(done.attempted_at, ready.attempted_at), - done.finalized_at, - COALESCE(done.created_at, ready.created_at, done.finalized_at), - COALESCE(done.unique_key, ready.unique_key), - COALESCE(done.unique_states, ready.unique_states), - COALESCE(done.payload, ready.payload, '{{}}'::jsonb) - FROM {done_child} AS done - LEFT JOIN {ready_child} AS ready - ON ready.ready_slot = done.ready_slot - AND ready.ready_generation = done.ready_generation - AND ready.queue = done.queue - AND ready.priority = done.priority - AND ready.enqueue_shard = done.enqueue_shard - AND ready.lane_seq = done.lane_seq - WHERE done.state = 'failed' - AND done.finalized_at >= now() - make_interval(secs => $1::bigint) - "# - ))) - .bind(failed_retention_secs) - .bind(state.0) - .bind(current_generation) - .execute(tx.as_mut()) - .await - .map_err(map_sqlx_error)? - .rows_affected(); - - if carried > 0 { - // This slot's live counter rows and delta segment are - // wiped below, so the carried rows' exact-count - // evidence moves with them: re-append positive deltas - // under the current slot, grouped exactly like the - // completion path's delta append. - sqlx::query(audited_sql(format!( + let failed_retention_secs = i64::try_from(failed_retention.as_secs()).unwrap_or(i64::MAX); + let retention_floor = failed_retention_secs > 0; + + // #337: failed terminal rows still inside the retention floor + // are re-homed into the live done segment before the TRUNCATE + // so they stay retryable. The ring rotation lock is held above, + // which serializes against rotate — the current slot (and its + // generation, read from the ledger cursor) cannot move while + // carried rows are re-inserted into it. + let carried_failed_rows = if retention_floor { + // Carried rows are widened to the self-contained synthetic + // done-row shape (the COALESCE chain mirrors + // `done_row_projection`) because the ready rows they would + // otherwise hydrate from are truncated with this slot. + // Deliberately no ON CONFLICT: lane_seq comes from + // never-resetting sequences, so a PK collision means + // corrupted terminal state and must abort the prune loudly + // rather than silently drop a terminal fact. + let carried = sqlx::query(audited_sql(format!( r#" - INSERT INTO {schema}.queue_terminal_count_deltas ( - ready_slot, - ready_generation, - queue, - priority, - enqueue_shard, - counter_bucket, - terminal_delta + INSERT INTO {schema}.done_entries ( + ready_slot, ready_generation, job_id, kind, queue, + args, state, priority, attempt, run_lease, + max_attempts, lane_seq, enqueue_shard, run_at, + attempted_at, finalized_at, created_at, unique_key, + unique_states, payload ) SELECT $2, $3, - queue, - priority, - enqueue_shard, - mod( - mod(job_id, {TERMINAL_COUNTER_BUCKETS}::bigint) - + {TERMINAL_COUNTER_BUCKETS}::bigint, - {TERMINAL_COUNTER_BUCKETS}::bigint - )::smallint AS counter_bucket, - count(*)::bigint - FROM {done_child} - WHERE state = 'failed' - AND finalized_at >= now() - make_interval(secs => $1::bigint) - GROUP BY queue, priority, enqueue_shard, counter_bucket - ORDER BY queue, priority, enqueue_shard, counter_bucket + done.job_id, + done.kind, + done.queue, + COALESCE(done.args, ready.args, '{{}}'::jsonb), + done.state, + done.priority, + done.attempt, + done.run_lease, + COALESCE(done.max_attempts, ready.max_attempts, 25::smallint), + done.lane_seq, + done.enqueue_shard, + COALESCE(done.run_at, ready.run_at, done.finalized_at), + COALESCE(done.attempted_at, ready.attempted_at), + done.finalized_at, + COALESCE(done.created_at, ready.created_at, done.finalized_at), + COALESCE(done.unique_key, ready.unique_key), + COALESCE(done.unique_states, ready.unique_states), + COALESCE(done.payload, ready.payload, '{{}}'::jsonb) + FROM {done_child} AS done + LEFT JOIN {ready_child} AS ready + ON ready.ready_slot = done.ready_slot + AND ready.ready_generation = done.ready_generation + AND ready.queue = done.queue + AND ready.priority = done.priority + AND ready.enqueue_shard = done.enqueue_shard + AND ready.lane_seq = done.lane_seq + WHERE done.state = 'failed' + AND done.finalized_at >= now() - make_interval(secs => $1::bigint) "# ))) .bind(failed_retention_secs) @@ -19052,187 +19010,232 @@ impl QueueStorage { .bind(current_generation) .execute(tx.as_mut()) .await - .map_err(map_sqlx_error)?; - } - carried - } else { - 0 - }; - - // #290: scan the about-to-be-truncated partition for the rollup - // fold. The rollup column is *permanent* state, so we MUST fold - // from ground truth (the `{done_child}` partition itself), not - // from `queue_terminal_live_counts` — the counter can drift - // briefly during a rolling upgrade from a pre-counter binary - // and folding drift into the rollup would bake it in forever. - // The counter rows for this slot are still cleaned up after the - // truncate; reads from the counter (queue_counts_exact in #305) - // may transiently disagree with the rollup until the operator - // runs `awa storage rebuild-terminal-counters`, but the rollup - // itself stays authoritative. See PR #304 reviewer finding - // "High: A1 can persist stale counter state before the - // read-switch PR" for the trade-off. - // - // Carried failed rows are excluded from both columns: they are - // still live in `done_entries`, so folding them into the - // permanent rollup would double-count them. - let pruned_terminal_counts: Vec<(String, i16, i64, i64)> = - sqlx::query_as(audited_sql(format!( - r#" - WITH done_counts AS ( - SELECT - queue, - priority, - (count(*) FILTER (WHERE state <> 'failed'))::bigint AS completed, - (count(*) FILTER ( + .map_err(map_sqlx_error)? + .rows_affected(); + + if carried > 0 { + // This slot's live counter rows and delta segment are + // wiped below, so the carried rows' exact-count + // evidence moves with them: re-append positive deltas + // under the current slot, grouped exactly like the + // completion path's delta append. + sqlx::query(audited_sql(format!( + r#" + INSERT INTO {schema}.queue_terminal_count_deltas ( + ready_slot, + ready_generation, + queue, + priority, + enqueue_shard, + counter_bucket, + terminal_delta + ) + SELECT + $2, + $3, + queue, + priority, + enqueue_shard, + mod( + mod(job_id, {TERMINAL_COUNTER_BUCKETS}::bigint) + + {TERMINAL_COUNTER_BUCKETS}::bigint, + {TERMINAL_COUNTER_BUCKETS}::bigint + )::smallint AS counter_bucket, + count(*)::bigint + FROM {done_child} WHERE state = 'failed' - AND ( - $2::boolean IS FALSE - OR finalized_at < now() - make_interval(secs => $1::bigint) - ) - ))::bigint AS failed - FROM {done_child} - GROUP BY queue, priority - ), - -- Scan the entire partition being truncated (all generations), - -- mirroring done_counts' whole-child scan above. The rotate guard - -- keeps a partition to one generation at prune time, so this is the - -- same set today; counting the whole child keeps the rollup fold - -- conservative even if that invariant is ever weakened (a stray - -- generation's batches would otherwise be truncated without being - -- folded into the rollup -> terminal-count undercount). - batch_rows AS ( - SELECT - batch.ready_generation, - batch.queue, - batch.priority, - item.job_id, - item.run_lease - FROM {receipt_batch_child} AS batch - CROSS JOIN LATERAL unnest( - batch.job_ids, - batch.run_leases - ) AS item(job_id, run_lease) - ), - batch_counts AS ( + AND finalized_at >= now() - make_interval(secs => $1::bigint) + GROUP BY queue, priority, enqueue_shard, counter_bucket + ORDER BY queue, priority, enqueue_shard, counter_bucket + "# + ))) + .bind(failed_retention_secs) + .bind(state.0) + .bind(current_generation) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + } + carried + } else { + 0 + }; + + // #290: scan the about-to-be-truncated partition for the rollup + // fold. The rollup column is *permanent* state, so we MUST fold + // from ground truth (the `{done_child}` partition itself), not + // from `queue_terminal_live_counts` — the counter can drift + // briefly during a rolling upgrade from a pre-counter binary + // and folding drift into the rollup would bake it in forever. + // The counter rows for this slot are still cleaned up after the + // truncate; reads from the counter (queue_counts_exact in #305) + // may transiently disagree with the rollup until the operator + // runs `awa storage rebuild-terminal-counters`, but the rollup + // itself stays authoritative. See PR #304 reviewer finding + // "High: A1 can persist stale counter state before the + // read-switch PR" for the trade-off. + // + // Carried failed rows are excluded from both columns: they are + // still live in `done_entries`, so folding them into the + // permanent rollup would double-count them. + let pruned_terminal_counts: Vec<(String, i16, i64, i64)> = + sqlx::query_as(audited_sql(format!( + r#" + WITH done_counts AS ( + SELECT + queue, + priority, + (count(*) FILTER (WHERE state <> 'failed'))::bigint AS completed, + (count(*) FILTER ( + WHERE state = 'failed' + AND ( + $2::boolean IS FALSE + OR finalized_at < now() - make_interval(secs => $1::bigint) + ) + ))::bigint AS failed + FROM {done_child} + GROUP BY queue, priority + ), + -- Scan the entire partition being truncated (all generations), + -- mirroring done_counts' whole-child scan above. The rotate guard + -- keeps a partition to one generation at prune time, so this is the + -- same set today; counting the whole child keeps the rollup fold + -- conservative even if that invariant is ever weakened (a stray + -- generation's batches would otherwise be truncated without being + -- folded into the rollup -> terminal-count undercount). + batch_rows AS ( + SELECT + batch.ready_generation, + batch.queue, + batch.priority, + item.job_id, + item.run_lease + FROM {receipt_batch_child} AS batch + CROSS JOIN LATERAL unnest( + batch.job_ids, + batch.run_leases + ) AS item(job_id, run_lease) + ), + batch_counts AS ( + SELECT + batch_rows.queue, + batch_rows.priority, + count(*)::bigint AS completed + FROM batch_rows + WHERE NOT EXISTS ( + SELECT 1 + FROM {receipt_tomb_child} AS tomb + WHERE tomb.ready_generation = batch_rows.ready_generation + AND tomb.job_id = batch_rows.job_id + AND tomb.run_lease = batch_rows.run_lease + ) + GROUP BY batch_rows.queue, batch_rows.priority + ), + keys AS ( + SELECT queue, priority FROM done_counts + UNION + SELECT queue, priority FROM batch_counts + ) SELECT - batch_rows.queue, - batch_rows.priority, - count(*)::bigint AS completed - FROM batch_rows - WHERE NOT EXISTS ( - SELECT 1 - FROM {receipt_tomb_child} AS tomb - WHERE tomb.ready_generation = batch_rows.ready_generation - AND tomb.job_id = batch_rows.job_id - AND tomb.run_lease = batch_rows.run_lease + keys.queue, + keys.priority, + ( + COALESCE(done_counts.completed, 0) + + COALESCE(batch_counts.completed, 0) + )::bigint AS pruned_completed_count, + COALESCE(done_counts.failed, 0)::bigint AS pruned_failed_count + FROM keys + LEFT JOIN done_counts USING (queue, priority) + LEFT JOIN batch_counts USING (queue, priority) + "# + ))) + .bind(failed_retention_secs) + .bind(retention_floor) + .fetch_all(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + + let truncate_started = Instant::now(); + self + .truncate_used_children_tx( + &mut tx, + &[ + &ready_child, + &claim_attempt_child, + &done_child, + &tomb_child, + &segment_child, + &receipt_batch_child, + &receipt_tomb_child, + &delta_child, + ], ) - GROUP BY batch_rows.queue, batch_rows.priority - ), - keys AS ( - SELECT queue, priority FROM done_counts - UNION - SELECT queue, priority FROM batch_counts - ) - SELECT - keys.queue, - keys.priority, - ( - COALESCE(done_counts.completed, 0) - + COALESCE(batch_counts.completed, 0) - )::bigint AS pruned_completed_count, - COALESCE(done_counts.failed, 0)::bigint AS pruned_failed_count - FROM keys - LEFT JOIN done_counts USING (queue, priority) - LEFT JOIN batch_counts USING (queue, priority) - "# + .await + .map_err(map_sqlx_error)?; + let truncate_duration = truncate_started.elapsed(); + if !pruned_terminal_counts.is_empty() { + // #371: append the pruned counts as delta rows instead + // of upserting `queue_terminal_rollups` here — the + // upsert under a pinned MVCC horizon left one + // unreclaimable dead rollup version per prune. The + // maintenance leader folds the deltas + // (`fold_terminal_rollup_deltas`) when the horizon is + // clear; exact readers add unfolded delta sums to + // their rollup reads. + self.append_terminal_rollup_deltas_tx( + &mut tx, + pruned_terminal_counts.into_iter(), + ) + .await?; + } + + // #290: the live counter rows for this slot are about to + // be orphans (their underlying done_entries rows just got + // truncated). Delete them in the same transaction. The + // rollup fold above already captured ground-truth from + // the partition scan; this just cleans up the counter + // index entries so a future insert into a re-rotated + // slot starts from zero. + sqlx::query(audited_sql(format!( + "DELETE FROM {schema}.queue_terminal_live_counts WHERE ready_slot = $1" ))) - .bind(failed_retention_secs) - .bind(retention_floor) - .fetch_all(tx.as_mut()) + .bind(slot) + .execute(tx.as_mut()) .await .map_err(map_sqlx_error)?; + Ok(PruneOutcome::Pruned { + slot, + generation, + carried_failed_rows, + durations: PruneDurations { + lock: lock_duration, + truncate: truncate_duration, + // Set once the transaction commits. + commit: Duration::ZERO, + }, + }) + } + .await; - let truncate_started = Instant::now(); - let truncate = self - .truncate_used_children_tx( - &mut tx, - &[ - &ready_child, - &claim_attempt_child, - &done_child, - &tomb_child, - &segment_child, - &receipt_batch_child, - &receipt_tomb_child, - &delta_child, - ], - ) - .await; - let truncate_duration = truncate_started.elapsed(); - - match truncate { - Ok(_) => { - if !pruned_terminal_counts.is_empty() { - // #371: append the pruned counts as delta rows instead - // of upserting `queue_terminal_rollups` here — the - // upsert under a pinned MVCC horizon left one - // unreclaimable dead rollup version per prune. The - // maintenance leader folds the deltas - // (`fold_terminal_rollup_deltas`) when the horizon is - // clear; exact readers add unfolded delta sums to - // their rollup reads. - self.append_terminal_rollup_deltas_tx( - &mut tx, - pruned_terminal_counts.into_iter(), - ) - .await?; - } - - // #290: the live counter rows for this slot are about to - // be orphans (their underlying done_entries rows just got - // truncated). Delete them in the same transaction. The - // rollup fold above already captured ground-truth from - // the partition scan; this just cleans up the counter - // index entries so a future insert into a re-rotated - // slot starts from zero. - sqlx::query(audited_sql(format!( - "DELETE FROM {schema}.queue_terminal_live_counts WHERE ready_slot = $1" - ))) - .bind(slot) - .execute(tx.as_mut()) - .await - .map_err(map_sqlx_error)?; - let commit_started = Instant::now(); - tx.commit().await.map_err(map_sqlx_error)?; - let commit_duration = commit_started.elapsed(); - if carried_failed_rows > 0 { - tracing::info!( - slot, - carried_failed_rows, - "Carried failed terminal rows inside the retention floor to the live done segment" - ); - } - Ok(PruneOutcome::Pruned { + let commit_started = Instant::now(); + let mut outcome = settle_prune_tx(tx, locked, PruneOutcome::Blocked { slot }).await?; + if let PruneOutcome::Pruned { + carried_failed_rows, + durations, + .. + } = &mut outcome + { + durations.commit = commit_started.elapsed(); + let carried_failed_rows = *carried_failed_rows; + if carried_failed_rows > 0 { + tracing::info!( slot, - generation, carried_failed_rows, - durations: PruneDurations { - lock: lock_duration, - truncate: truncate_duration, - commit: commit_duration, - }, - }) - } - Err(err) if is_lock_contention_error(&err) => { - let _ = tx.rollback().await; - Ok(PruneOutcome::Blocked { slot }) - } - Err(err) => { - let _ = tx.rollback().await; - Err(map_sqlx_error(err)) + "Carried failed terminal rows inside the retention floor to the live done segment" + ); } } + Ok(outcome) } #[tracing::instrument( @@ -19308,82 +19311,68 @@ impl QueueStorage { let lease_child = lease_child_name(schema, slot as usize); - set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; + let locked: Result = async { + set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - let lock_started = Instant::now(); - let lock_table = sqlx::query(audited_sql(format!( - "LOCK TABLE {lease_child} IN ACCESS EXCLUSIVE MODE" - ))) - .execute(tx.as_mut()) - .await; - let lock_duration = lock_started.elapsed(); + let lock_started = Instant::now(); + sqlx::query(audited_sql(format!( + "LOCK TABLE {lease_child} IN ACCESS EXCLUSIVE MODE" + ))) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + let lock_duration = lock_started.elapsed(); - if let Err(err) = lock_table { - let _ = tx.rollback().await; - if is_lock_contention_error(&err) { - return Ok(PruneOutcome::Blocked { slot }); + // The ring rotation serialization held above keeps the cursor + // stable, but keep the explicit recheck to document the truncate + // precondition. + let (current_slot, _) = self + .ring_cursor_tx(&mut tx, RingFamily::Lease, authority) + .await?; + + if current_slot == slot { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::LeaseCurrent, + count: 0, + }); } - return Err(map_sqlx_error(err)); - } - // The ring rotation serialization held above keeps the cursor - // stable, but keep the explicit recheck to document the truncate - // precondition. - let (current_slot, _) = self - .ring_cursor_tx(&mut tx, RingFamily::Lease, authority) - .await?; + let active_leases = Self::relation_has_rows_tx(&mut tx, &lease_child).await?; - if current_slot == slot { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::LeaseCurrent, - count: 0, - }); - } - - let active_leases = Self::relation_has_rows_tx(&mut tx, &lease_child).await?; + if active_leases { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::LeaseActive, + count: busy_indicator(active_leases), + }); + } - if active_leases { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { + let truncate_started = Instant::now(); + self.truncate_used_children_tx(&mut tx, &[&lease_child]) + .await + .map_err(map_sqlx_error)?; + let truncate_duration = truncate_started.elapsed(); + Ok(PruneOutcome::Pruned { slot, - reason: SkipReason::LeaseActive, - count: busy_indicator(active_leases), - }); + generation, + carried_failed_rows: 0, + durations: PruneDurations { + lock: lock_duration, + truncate: truncate_duration, + // Set once the transaction commits. + commit: Duration::ZERO, + }, + }) } + .await; - let truncate_started = Instant::now(); - let truncate = self - .truncate_used_children_tx(&mut tx, &[&lease_child]) - .await; - let truncate_duration = truncate_started.elapsed(); - - match truncate { - Ok(_) => { - let commit_started = Instant::now(); - tx.commit().await.map_err(map_sqlx_error)?; - let commit_duration = commit_started.elapsed(); - Ok(PruneOutcome::Pruned { - slot, - generation, - carried_failed_rows: 0, - durations: PruneDurations { - lock: lock_duration, - truncate: truncate_duration, - commit: commit_duration, - }, - }) - } - Err(err) if is_lock_contention_error(&err) => { - let _ = tx.rollback().await; - Ok(PruneOutcome::Blocked { slot }) - } - Err(err) => { - let _ = tx.rollback().await; - Err(map_sqlx_error(err)) - } + let commit_started = Instant::now(); + let mut outcome = settle_prune_tx(tx, locked, PruneOutcome::Blocked { slot }).await?; + if let PruneOutcome::Pruned { durations, .. } = &mut outcome { + durations.commit = commit_started.elapsed(); } + Ok(outcome) } pub async fn vacuum_leases(&self, pool: &PgPool) -> Result<(), AwaError> { @@ -19687,116 +19676,103 @@ impl QueueStorage { }); } - set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - - let lock_started = Instant::now(); - let lock_tables = sqlx::query(audited_sql(format!( - "LOCK TABLE {claim_child}, {claim_batch_child}, {closure_child}, {closure_batch_child} IN ACCESS EXCLUSIVE MODE" - ))) - .execute(tx.as_mut()) - .await; - let lock_duration = lock_started.elapsed(); - - if let Err(err) = lock_tables { - let _ = tx.rollback().await; - if is_lock_contention_error(&err) { - return Ok(PruneOutcome::Blocked { slot }); - } - return Err(map_sqlx_error(err)); - } + let locked: Result = async { + set_prune_lock_timeout_tx(&mut tx, self.prune_lock_timeout).await?; - // After taking ACCESS EXCLUSIVE, recheck that the slot is still - // not the current one. The ring rotation serialization should - // already make this stable, but keeping the explicit gate documents - // the truncate precondition. - let (current_slot, _) = self - .ring_cursor_tx(&mut tx, RingFamily::Claim, authority) - .await?; + let lock_started = Instant::now(); + sqlx::query(audited_sql(format!( + "LOCK TABLE {claim_child}, {claim_batch_child}, {closure_child}, {closure_batch_child} IN ACCESS EXCLUSIVE MODE" + ))) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + let lock_duration = lock_started.elapsed(); - if current_slot == slot { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::ClaimCurrent, - count: 0, - }); - } + // After taking ACCESS EXCLUSIVE, recheck that the slot is still + // not the current one. The ring rotation serialization should + // already make this stable, but keeping the explicit gate documents + // the truncate precondition. + let (current_slot, _) = self + .ring_cursor_tx(&mut tx, RingFamily::Claim, authority) + .await?; - let open_claims = claim_prune_has_open_claims_tx( - &mut tx, - schema, - &claim_child, - &claim_batch_child, - &closure_child, - &closure_batch_child, - ) - .await?; - if open_claims { - tx.commit().await.map_err(map_sqlx_error)?; - return Ok(PruneOutcome::SkippedActive { - slot, - reason: SkipReason::ClaimOpen, - count: busy_indicator(open_claims), - }); - } + if current_slot == slot { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::ClaimCurrent, + count: 0, + }); + } - let truncate_started = Instant::now(); - let truncate = self - .truncate_used_children_tx( + let open_claims = claim_prune_has_open_claims_tx( &mut tx, - &[ - &claim_child, - &claim_batch_child, - &closure_child, - &closure_batch_child, - ], + schema, + &claim_child, + &claim_batch_child, + &closure_child, + &closure_batch_child, ) - .await; - let truncate_duration = truncate_started.elapsed(); + .await?; + if open_claims { + return Ok(PruneOutcome::SkippedActive { + slot, + reason: SkipReason::ClaimOpen, + count: busy_indicator(open_claims), + }); + } - match truncate { - Ok(_) => { - sqlx::query(audited_sql(format!( - r#" - UPDATE {schema}.claim_ring_slots - SET rescue_cursor_claimed_at = '-infinity'::timestamptz, - rescue_cursor_job_id = 0, - rescue_cursor_run_lease = 0, - deadline_cursor_deadline_at = '-infinity'::timestamptz, - deadline_cursor_job_id = 0, - deadline_cursor_run_lease = 0, - batch_deadline_cursor_deadline_at = '-infinity'::timestamptz, - batch_deadline_cursor_batch_id = 0 - WHERE slot = $1 - "# - ))) - .bind(slot) - .execute(tx.as_mut()) + let truncate_started = Instant::now(); + self + .truncate_used_children_tx( + &mut tx, + &[ + &claim_child, + &claim_batch_child, + &closure_child, + &closure_batch_child, + ], + ) .await .map_err(map_sqlx_error)?; - let commit_started = Instant::now(); - tx.commit().await.map_err(map_sqlx_error)?; - let commit_duration = commit_started.elapsed(); - Ok(PruneOutcome::Pruned { - slot, - generation, - carried_failed_rows: 0, - durations: PruneDurations { - lock: lock_duration, - truncate: truncate_duration, - commit: commit_duration, - }, - }) - } - Err(err) if is_lock_contention_error(&err) => { - let _ = tx.rollback().await; - Ok(PruneOutcome::Blocked { slot }) - } - Err(err) => { - let _ = tx.rollback().await; - Err(map_sqlx_error(err)) - } + let truncate_duration = truncate_started.elapsed(); + sqlx::query(audited_sql(format!( + r#" + UPDATE {schema}.claim_ring_slots + SET rescue_cursor_claimed_at = '-infinity'::timestamptz, + rescue_cursor_job_id = 0, + rescue_cursor_run_lease = 0, + deadline_cursor_deadline_at = '-infinity'::timestamptz, + deadline_cursor_job_id = 0, + deadline_cursor_run_lease = 0, + batch_deadline_cursor_deadline_at = '-infinity'::timestamptz, + batch_deadline_cursor_batch_id = 0 + WHERE slot = $1 + "# + ))) + .bind(slot) + .execute(tx.as_mut()) + .await + .map_err(map_sqlx_error)?; + Ok(PruneOutcome::Pruned { + slot, + generation, + carried_failed_rows: 0, + durations: PruneDurations { + lock: lock_duration, + truncate: truncate_duration, + // Set once the transaction commits. + commit: Duration::ZERO, + }, + }) } + .await; + + let commit_started = Instant::now(); + let mut outcome = settle_prune_tx(tx, locked, PruneOutcome::Blocked { slot }).await?; + if let PruneOutcome::Pruned { durations, .. } = &mut outcome { + durations.commit = commit_started.elapsed(); + } + Ok(outcome) } fn job_id_sequence(&self) -> String { diff --git a/awa-python/python/awa/client.py b/awa-python/python/awa/client.py index 43b13eb68..733114388 100644 --- a/awa-python/python/awa/client.py +++ b/awa-python/python/awa/client.py @@ -971,9 +971,10 @@ async def start( ``queue_storage_prune_lock_timeout_ms`` sets the PostgreSQL ``lock_timeout`` the maintenance leader uses when pruning the queue, lease and claim rings (default 10 ms). Each lock acquisition gets its - own timeout; this does not bound the whole prune. Queue prune waits - only on ``ready_segments``; its other partition locks use ``NOWAIT``. A - lock timeout rolls back the prune and counts it as ``blocked``; the + own timeout; this does not bound the whole prune. Among queue prune's + initial partition locks, only ``ready_segments`` waits; the others use + ``NOWAIT``. Later reads and writes also run under the timeout. A lock + timeout rolls back the prune and counts it as ``blocked``; the maintenance loop retries on a later tick. Raise it when ``blocked`` outcomes persist, keeping it well below the server's ``deadlock_timeout`` and ``statement_timeout`` (a warning is logged at diff --git a/awa/tests/queue_storage_runtime_test.rs b/awa/tests/queue_storage_runtime_test.rs index 9bf5c8468..4e671b77d 100644 --- a/awa/tests/queue_storage_runtime_test.rs +++ b/awa/tests/queue_storage_runtime_test.rs @@ -15970,6 +15970,181 @@ async fn test_queue_storage_prune_oldest_blocks_on_reader_lock() { ); } +/// The prune `lock_timeout` covers every statement after it is set, not +/// only the `LOCK TABLE` on the slot's children. A statement that waits on +/// another table's lock — here the failed-row carry, its count deltas, the +/// rollup delta append and the live-counter cleanup — must roll the whole prune back +/// and report `Blocked`, leaving the slot to the next attempt. +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_queue_storage_prune_lock_timeout_after_child_locks_reports_blocked() { + let (_db_guard, pool) = setup_pool(10).await; + let queue = "qs_prune_late_lock_timeout"; + let schema = "awa_qs_prune_late_lock_timeout"; + let store = create_store(&pool, schema).await; + + store + .enqueue_batch(&pool, queue, 1, 1) + .await + .expect("enqueue completed job"); + let claimed = store + .claim_batch(&pool, queue, 1) + .await + .expect("claim completed job"); + store + .complete_batch(&pool, &claimed) + .await + .expect("complete job"); + + let failed_job_id = enqueue_job( + &pool, + &store, + &CompleteJob { id: 1 }, + InsertOpts { + queue: queue.to_string(), + ..Default::default() + }, + ) + .await; + let claimed = store + .claim_runtime_batch(&pool, queue, 1, Duration::from_secs(30)) + .await + .expect("claim failing job") + .into_iter() + .next() + .expect("missing claimed job"); + store + .fail_terminal(&pool, failed_job_id, claimed.job.run_lease, "boom", None) + .await + .expect("fail job") + .expect("running job should fail"); + + let rotated = store.rotate(&pool).await.expect("rotate"); + assert!( + matches!(rotated, RotateOutcome::Rotated { slot: 1, .. }), + "unexpected rotate outcome: {rotated:?}" + ); + + let retention = Duration::from_secs(3600); + for held in [ + format!("{schema}.done_entries_1"), + format!("{schema}.queue_terminal_count_deltas_1"), + format!("{schema}.queue_terminal_rollup_deltas"), + format!("{schema}.queue_terminal_live_counts"), + ] { + let mut holder = pool.begin().await.expect("begin lock holder"); + sqlx::query(audited_sql(format!("LOCK TABLE {held} IN SHARE MODE"))) + .execute(holder.as_mut()) + .await + .expect("hold share lock"); + + let outcome = store.prune_oldest(&pool, retention).await; + assert!( + matches!(outcome, Ok(PruneOutcome::Blocked { slot: 0 })), + "prune waiting on {held} should report Blocked, got {outcome:?}" + ); + + holder.rollback().await.expect("release share lock"); + + assert_eq!( + done_entries_count(&pool, schema, queue).await, + 2, + "blocked prune on {held} must not truncate or carry rows" + ); + let rollup_rows: i64 = sqlx::query_scalar(audited_sql(format!( + "SELECT count(*)::bigint FROM {schema}.queue_terminal_rollup_deltas" + ))) + .fetch_one(&pool) + .await + .expect("count rollups"); + assert_eq!( + rollup_rows, 0, + "blocked prune on {held} must not fold rollups" + ); + assert_invariant_holds( + &pool, + schema, + queue, + &format!("after prune blocked on {held}"), + ) + .await; + } + + let pruned = store + .prune_oldest(&pool, retention) + .await + .expect("prune after locks released"); + assert!( + matches!( + pruned, + PruneOutcome::Pruned { + slot: 0, + carried_failed_rows: 1, + .. + } + ), + "unexpected prune outcome after locks released: {pruned:?}" + ); + assert_invariant_holds(&pool, schema, queue, "after prune").await; + let counts = store.queue_counts(&pool, queue).await.expect("counts"); + assert_eq!(counts.terminal, 2, "rollup (1) + carried live row (1)"); +} + +/// Terminal-delta rollup shares prune's lock timeout. A timeout on the +/// live-counter fold, after the delta child is locked, must report a blocked +/// slot rather than fail the rollup pass, and the pass stops there instead of +/// waiting out the same timeout on every remaining slot. +#[tokio::test(flavor = "multi_thread", worker_threads = 4)] +async fn test_queue_terminal_count_delta_rollup_lock_timeout_after_child_lock_reports_blocked() { + let (_db_guard, pool) = setup_pool(10).await; + let queue = "qs_terminal_delta_rollup_late_lock"; + let schema = "awa_qs_terminal_delta_rollup_late_lock"; + let store = create_store(&pool, schema).await; + + for _ in 0..2 { + store + .enqueue_batch(&pool, queue, 1, 3) + .await + .expect("enqueue"); + let claimed = store.claim_batch(&pool, queue, 3).await.expect("claim"); + store + .complete_batch(&pool, &claimed) + .await + .expect("complete"); + match store.rotate(&pool).await.expect("rotate") { + RotateOutcome::Rotated { .. } => {} + other => panic!("expected Rotated, got {other:?}"), + } + } + + let mut holder = pool.begin().await.expect("begin lock holder"); + sqlx::query(audited_sql(format!( + "LOCK TABLE {schema}.queue_terminal_live_counts IN SHARE MODE" + ))) + .execute(holder.as_mut()) + .await + .expect("hold share lock"); + + let outcome = store.rollup_terminal_count_deltas(&pool, 4).await; + holder.rollback().await.expect("release share lock"); + let outcome = outcome.expect("rollup waiting on live counts should not error"); + assert_eq!(outcome.rolled_slots, 0); + assert_eq!( + outcome.blocked_slots, 1, + "the pass stops at the first blocked slot" + ); + assert_eq!(live_count_sum(&pool, schema, queue).await, 0); + assert_eq!(terminal_delta_sum(&pool, schema, queue).await, 6); + + let outcome = store + .rollup_terminal_count_deltas(&pool, 4) + .await + .expect("rollup after lock released"); + assert_eq!(outcome.rolled_slots, 2); + assert_eq!(outcome.blocked_slots, 0); + assert_eq!(live_count_sum(&pool, schema, queue).await, 6); + assert_eq!(terminal_delta_sum(&pool, schema, queue).await, 0); +} + #[tokio::test(flavor = "multi_thread", worker_threads = 4)] async fn test_queue_prune_allows_segment_reader_to_finish_claim_lock_order() { let (_db_guard, pool) = setup_pool(8).await; diff --git a/docs/configuration.md b/docs/configuration.md index 66f9fb3e6..f4e36389f 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -581,7 +581,7 @@ await client.start( | `queue_rotate_interval` | `1000ms` | How often ready/terminal segments rotate | | `lease_rotate_interval` | `1000ms` | How often lease segments rotate | | `claim_rotate_interval` | matches `queue_rotate_interval` | How often the ADR-023 claim-ring rotates. Set with `ClientBuilder::claim_rotate_interval` (Rust) or `queue_storage_claim_rotate_interval_ms` (Python). Test harnesses sometimes set this to a long interval to pin claim-ring layout for deterministic count assertions. | -| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); queue ring prune waits under it only on the `ready_segments` partition. The timeout applies separately to each lock acquisition, not to the whole prune. A lock timeout rolls the prune back, is counted as `blocked`, and is retried on a later maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero and at most `2147483647` ms; keep it well below `deadlock_timeout` and `statement_timeout`. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | +| `prune_lock_timeout` | `10ms` | The PostgreSQL `lock_timeout` the maintenance leader applies when it takes the exclusive locks to reclaim a queue, lease or claim ring partition (and when it folds terminal-count deltas); among queue prune's initial partition locks, only `ready_segments` waits under it; later reads and writes also run under it. The timeout applies separately to each lock acquisition, not to the whole prune. A lock timeout rolls the prune back, is counted as `blocked`, and is retried on a later maintenance tick. Set with `ClientBuilder::prune_lock_timeout` (Rust) or `queue_storage_prune_lock_timeout_ms` (Python). Must be greater than zero and at most `2147483647` ms; keep it well below `deadlock_timeout` and `statement_timeout`. The short default keeps prune's pending `ACCESS EXCLUSIVE` request from stalling claims and enqueues queued behind it. See below for when to raise it. | | `ring_rotation_cadence` | 5 s / 2 MiB target / 256 rows / 60 s | A non-empty slot becomes eligible after `min_slot_age` since the first non-empty observation once it holds `min_slot_rows`, when `target_slot_bytes` is reached, or after `max_slot_age` regardless of rows (so a trickle of writes neither seals a nearly empty slot every window nor keeps one open indefinitely). Python: `queue_storage_rotate_min_slot_rows`, `queue_storage_rotate_max_slot_age_ms`. Counts total physical storage, including indexes and TOAST. Empty slots bypass the cadence. The minimum age uses a monotonic clock and resets on an empty observation or leader change; `max_slot_age` also counts from when the slot opened on the database clock, so a leader change does not restart it, except under compat (pre-flip) authority when an older rotator left no ledger row for the slot. `max_slot_age` makes a slot eligible to seal; the busy and reuse checks still decide when it is reclaimed. Configure with `ClientBuilder::ring_rotation_cadence` (Rust) or `queue_storage_rotate_min_slot_age_ms` / `queue_storage_rotate_target_slot_bytes` (Python). A zero byte target disables the size trigger, a zero `min_slot_rows` disables the row floor, and a zero `max_slot_age` disables the ceiling. A row floor needs a size target or a ceiling, and a queue-storage client refuses to build without one, because lease rows are deleted as attempts finish and a lease slot may never reach the floor. A zero `min_slot_age`, or `RingRotationCadence::EAGER`, permits sealing on every tick whatever the other settings. The target is sampled and does not bound retained storage. | The benchmark harness in [postgresql-job-queue-benchmarking](https://github.com/hardbyte/postgresql-job-queue-benchmarking) reads `QUEUE_SLOT_COUNT`, `LEASE_SLOT_COUNT`, `CLAIM_SLOT_COUNT`, `QUEUE_STRIPE_COUNT`, and `LEASE_CLAIM_RECEIPTS` from the environment. Those env vars are benchmark configuration, not general worker-runtime configuration. @@ -596,7 +596,7 @@ Use the defaults unless you have a reason not to: - Increase `lease_slot_count` if lease churn is high enough that dead tuples in the lease ring stop collapsing promptly. - Increase `claim_slot_count` if the rotation cadence (`claim_rotate_interval`) plus the slot count combine to a partition retention window shorter than your longest in-flight zero-deadline short job; running out of empty slots forces `rotate_claims` to return `SkippedBusy` and the receipt-plane churn falls back onto a smaller working set of partitions. - Increase `queue_stripe_count` only for measured workloads where many small replicas contend on the same logical queue. This is queue-storage configuration, not a per-queue `QueueConfig` field: it gives each logical queue the same number of physical stripes. Striping spreads a hot logical queue over `queue#N` physical coordination paths, but it weakens perfect global ordering and can regress calmer shapes if overused. For single hot-queue workloads, benchmark `2` stripes first; higher values should be treated as workload-specific tuning rather than a general default. -- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Queue ring prune waits under the timeout only on the `ready_segments` partition and takes its other partitions with `NOWAIT`, so a longer timeout does not help when readers hold those. Raise it in small steps (for example `50ms`, then `100ms`, then `250ms`) and keep it well below PostgreSQL's `deadlock_timeout` (default `1s`) and below any `statement_timeout` on the pool's connections. A single lock wait that reaches `deadlock_timeout` makes PostgreSQL run its deadlock detector, and if claims or enqueues are part of a lock cycle with it, the detector can cancel them rather than the prune; a short `lock_timeout` abandons the prune first, so the prune is always the one that gives way. A `statement_timeout` at or below the lock timeout cancels the prune statement before the lock timeout fires, so it fails with an error instead of reporting `blocked`. Startup logs a warning when the configured timeout is at or above either setting. While prune waits, new accesses to the same partition also queue behind its lock request, so a longer timeout trades claim latency for reclamation. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. +- Increase `prune_lock_timeout` when `increase(awa_maintenance_prune_attempts_total{awa_ring_outcome="blocked"}[15m])` stays above zero and the rings stop recycling, typically because frequent short reads of the ring partitions (admin or dashboard queries over the queue-storage tables) hold a conflicting lock at the instant prune tries. A stalled ring grows its current slot, which makes those queries slower and the contention worse. Among its initial partition locks, queue ring prune waits under the timeout only on `ready_segments` and takes the others with `NOWAIT`, so a longer timeout does not help when readers hold those. Later reads and writes also run under the timeout. Raise it in small steps (for example `50ms`, then `100ms`, then `250ms`) and keep it well below PostgreSQL's `deadlock_timeout` (default `1s`) and below any `statement_timeout` on the pool's connections. A single lock wait that reaches `deadlock_timeout` makes PostgreSQL run its deadlock detector, and if claims or enqueues are part of a lock cycle with it, the detector can cancel them rather than the prune; a short `lock_timeout` abandons the prune first, so the prune is always the one that gives way. A `statement_timeout` at or below the lock timeout cancels the prune statement before the lock timeout fires, so it fails with an error instead of reporting `blocked`. Startup logs a warning when the configured timeout is at or above either setting. While prune waits, new accesses to the same partition also queue behind its lock request, so a longer timeout trades claim latency for reclamation. Shortening the readers is the more durable fix when they run longer than a few hundred milliseconds. Watch `awa_maintenance_prune_attempts_total` by `awa_ring` and `awa_ring_outcome`: `pruned` should advance steadily, `blocked` means the lock timeout expired, `skipped_active` (with `awa_ring_reason`) means live rows kept the slot, `backed_off` means prune was skipped for a few ticks after repeated `skipped_active`, and `error` is a database failure. - Increase rotation intervals to reduce partition churn and metadata activity. - Decrease rotation intervals to tighten dead-tuple bounds at the cost of more frequent rotate/prune work.