fix(gw): stop reaping in-use connection pools after 2h of uptime · documentdb/documentdb@8a1914f · GitHub
Skip to content

Commit 8a1914f

Browse files
fix(gw): stop reaping in-use connection pools after 2h of uptime
`ConnectionPool::last_used_nanos` holds nanoseconds since the process epoch, and that is how `last_used()` decodes it. Both acquisition paths were writing it with `EpochClock::almost_now_timestamp()`, which returns seconds since the UNIX epoch. Decoded as nanoseconds, that lands ~1.785s after process start and then advances a nanosecond per second, so the stamp was effectively frozen. `last_used().elapsed()` therefore measured process uptime rather than pool idleness. The reaper wakes every 300s and disposes pools idle beyond POSTGRES_POOL_DISPOSE_INTERVAL_SEC (7200s); with a frozen stamp the tick at t=7200s reads 7198.2s and spares the pool, and the tick at t=7500s reads 7498.2s and evicts it. From then on every user data pool is evicted regardless of how heavily it is in use, and re-evicted on each subsequent tick. `get_data_pool` cannot rebuild an evicted pool because the user password is not retained past authentication, so requests from an already-authenticated client fail from 2h05m of uptime onward. The client sees "An unexpected internal error has occurred."; only the gateway log carries "Connection pool missing for user." Route both acquisition paths through a single `touch_last_used` helper that writes the encoding `last_used` decodes. Use the precise `Instant::now()` rather than either coarse `EpochClock` reading: the coarse updater is a tokio task bound to whichever runtime first initialises the global clock, and the reaper's only input should not depend on that task still being alive. The syscall is ~20ns on a path that then checks out a pooled connection. Regression introduced in v0.114-0; v0.112-0 and v0.113-0 are unaffected. Adds three regression tests that fail on the unfixed code, a `wait_for_epoch_uptime` test helper that makes process uptime a controllable input, and an RCA under docs/rca/. Validated by an 8h three-arm soak on documentdb-local:pg17-0.114.0 in which the arms differ only by this fix: stock v0.114.0 first failed at 2h05m00.3s and a locally built unmodified v0.114-0 at 2h05m00.1s, while the fixed build ran 8h and 28,680 operations with zero occurrences and its reaper ticking 97 times. Details in the RCA. Signed-off-by: Guanzhou Song <guanzhousong@microsoft.com>
1 parent fd46318 commit 8a1914f

5 files changed

Lines changed: 137 additions & 9 deletions

File tree

‎CHANGELOG.md‎

Lines changed: 1 addition & 0 deletions

‎pg_documentdb_gw/documentdb_gateway_core/src/postgres/conn_mgmt/connection_pool.rs‎

Lines changed: 76 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ use crate::{
4242
QueryCatalog,
4343
},
4444
telemetry::TracingConfig,
45-
time::{self, EpochClock},
45+
time,
4646
};
4747

4848
fn pg_configuration(
@@ -147,7 +147,13 @@ pub struct ConnectionPool {
147147
/// `RecyclingMethod::Clean` to reset all session state when a
148148
/// connection is returned
149149
timeout_pool: DeadpoolPool<InstrumentedManager>,
150-
/// Nanosecond offset from `EPOCH` of the last `acquire_connection` call.
150+
/// Nanosecond offset from the process epoch of the last
151+
/// `acquire_connection` call. Only ever written through
152+
/// [`ConnectionPool::touch_last_used`] and read through
153+
/// [`ConnectionPool::last_used`], which own that encoding — writing a
154+
/// timestamp in any other unit or base here silently corrupts every
155+
/// idleness decision made about this pool.
156+
///
151157
/// Uses `AtomicU64` instead of `RwLock<Instant>` to avoid async lock
152158
/// overhead on the hot acquire path.
153159
last_used_nanos: AtomicU64,
@@ -278,8 +284,7 @@ impl ConnectionPool {
278284
pub async fn acquire_connection(
279285
&self,
280286
) -> std::result::Result<PoolConnection, deadpool_postgres::PoolError> {
281-
self.last_used_nanos
282-
.store(EpochClock::almost_now_timestamp(), Ordering::Relaxed);
287+
self.touch_last_used();
283288

284289
self.pool.get().await.inspect_err(|error| {
285290
self.metrics.record_timeout_if_pool_timeout(error);
@@ -306,8 +311,7 @@ impl ConnectionPool {
306311
pub async fn acquire_timeout_connection(
307312
&self,
308313
) -> std::result::Result<PoolConnection, deadpool_postgres::PoolError> {
309-
self.last_used_nanos
310-
.store(EpochClock::almost_now_timestamp(), Ordering::Relaxed);
314+
self.touch_last_used();
311315

312316
self.timeout_pool.get().await.inspect_err(|error| {
313317
self.metrics.record_timeout_if_pool_timeout(error);
@@ -333,6 +337,26 @@ impl ConnectionPool {
333337
self.metrics.record_connection_timeout();
334338
}
335339

340+
/// Marks the pool as used as of now.
341+
///
342+
/// Deliberately uses the precise `Instant::now()` rather than either of the
343+
/// `EpochClock` coarse readings. This stamp is the sole input to the pool
344+
/// reaper, so it must not depend on the coarse clock's updater task still
345+
/// being alive on the runtime that happened to initialise it, and it must
346+
/// stay in the encoding [`Self::last_used`] decodes: nanoseconds since the
347+
/// process epoch. `EpochClock::almost_now_timestamp()` in particular looks
348+
/// interchangeable here and is not — it returns *seconds since the UNIX
349+
/// epoch*, which decodes as a point roughly two seconds after process start
350+
/// that then advances by a nanosecond per second, making every pool look
351+
/// idle for as long as the process has been up.
352+
///
353+
/// The `Instant::now()` syscall costs ~20ns against a call that goes on to
354+
/// check out a pooled connection, so the coarse clock buys nothing here.
355+
fn touch_last_used(&self) {
356+
self.last_used_nanos
357+
.store(time::instant_to_u64(Instant::now()), Ordering::Relaxed);
358+
}
359+
336360
pub fn last_used(&self) -> Instant {
337361
time::u64_to_instant(self.last_used_nanos.load(Ordering::Relaxed))
338362
}
@@ -391,9 +415,14 @@ mod tests {
391415

392416
use crate::{
393417
postgres::create_query_catalog,
394-
testing::{test_connection_pool, test_setup_configuration},
418+
testing::{test_connection_pool, test_setup_configuration, wait_for_epoch_uptime},
395419
};
396420

421+
/// Long enough that a stamp written in the wrong unit or base cannot look
422+
/// recent: such a stamp decodes to roughly two seconds past the epoch and
423+
/// then stays effectively frozen there.
424+
const EPOCH_UPTIME_FOR_IDLENESS_ASSERTS: Duration = Duration::from_secs(5);
425+
397426
#[tokio::test]
398427
async fn test_new_with_user_with_valid_config_creates_pool() {
399428
let setup_config = test_setup_configuration();
@@ -525,6 +554,46 @@ mod tests {
525554
assert!(pool.last_used().elapsed() < Duration::from_secs(5));
526555
}
527556

557+
#[tokio::test]
558+
async fn test_last_used_after_acquire_connection_reports_pool_as_recently_used() {
559+
let setup_config = test_setup_configuration();
560+
let pool =
561+
test_connection_pool(&setup_config, &setup_config.postgres_system_user.clone(), 2)
562+
.await;
563+
564+
wait_for_epoch_uptime(EPOCH_UPTIME_FOR_IDLENESS_ASSERTS).await;
565+
566+
// The last-used stamp is written before the pool is touched, so whether
567+
// a local Postgres is reachable does not affect what is asserted here.
568+
let _ = pool.acquire_connection().await;
569+
570+
let idle_for = pool.last_used().elapsed();
571+
assert!(
572+
idle_for < Duration::from_secs(1),
573+
"a just-acquired pool must not look idle, but last_used() reports {idle_for:?} of \
574+
idleness"
575+
);
576+
}
577+
578+
#[tokio::test]
579+
async fn test_last_used_after_acquire_timeout_connection_reports_pool_as_recently_used() {
580+
let setup_config = test_setup_configuration();
581+
let pool =
582+
test_connection_pool(&setup_config, &setup_config.postgres_system_user.clone(), 2)
583+
.await;
584+
585+
wait_for_epoch_uptime(EPOCH_UPTIME_FOR_IDLENESS_ASSERTS).await;
586+
587+
let _ = pool.acquire_timeout_connection().await;
588+
589+
let idle_for = pool.last_used().elapsed();
590+
assert!(
591+
idle_for < Duration::from_secs(1),
592+
"a just-acquired pool must not look idle, but last_used() reports {idle_for:?} of \
593+
idleness"
594+
);
595+
}
596+
528597
#[test]
529598
fn test_pg_configuration_with_password_sets_password() {
530599
let setup_config = test_setup_configuration();

‎pg_documentdb_gw/documentdb_gateway_core/src/postgres/conn_mgmt/pool_manager.rs‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -342,6 +342,7 @@ mod tests {
342342
configuration::{CertInputType, CertificateOptions, DocumentDBSetupConfiguration},
343343
error::{ErrorCode, ErrorKind},
344344
postgres::create_query_catalog,
345+
testing::wait_for_epoch_uptime,
345346
};
346347

347348
#[derive(Debug)]
@@ -749,6 +750,44 @@ mod tests {
749750
assert_eq!(2, pool_manager.report_pool_stats().len());
750751
}
751752

753+
#[tokio::test]
754+
async fn test_clean_unused_pools_with_actively_used_pool_keeps_pool_reachable() {
755+
yield_now().await;
756+
757+
let dynamic_configuration = MaxConnectionConfig {
758+
max_conn: 100.into(),
759+
};
760+
let pool_manager = test_pool_manager();
761+
762+
pool_manager
763+
.allocate_data_pool("user", "password", &dynamic_configuration)
764+
.unwrap();
765+
766+
wait_for_epoch_uptime(Duration::from_secs(5)).await;
767+
768+
// Drive the pool the way a live request does. The acquisition itself may
769+
// fail without a local Postgres, but the last-used stamp is written
770+
// before the pool is touched, which is what the reaper reads.
771+
let _ = pool_manager
772+
.get_data_pool("user", &dynamic_configuration)
773+
.unwrap()
774+
.acquire_connection()
775+
.await;
776+
777+
pool_manager.clean_unused_pools(Duration::from_secs(1));
778+
779+
// The reaper has to key off how long a pool has been idle, not off how
780+
// long the process has been running. Evicting a pool that is still in
781+
// active use makes every subsequent request for that user fail with
782+
// "Connection pool missing for user." until the client re-authenticates.
783+
assert!(
784+
pool_manager
785+
.get_data_pool("user", &dynamic_configuration)
786+
.is_ok(),
787+
"a data pool that was just used was reaped as unused"
788+
);
789+
}
790+
752791
#[tokio::test]
753792
async fn test_report_pool_stats_flushes_interval_metrics_from_system_pools() {
754793
yield_now().await;

‎pg_documentdb_gw/documentdb_gateway_core/src/testing/mod.rs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@ pub use op_msg::{
2424
build_document_sequence_section, build_op_msg_parts, build_op_msg_parts_with_sections,
2525
build_op_msg_request, build_raw_document, decode_op_msg_response, decode_op_msg_responses,
2626
};
27-
pub use pool::{test_connection_pool, test_setup_configuration};
27+
pub use pool::{test_connection_pool, test_setup_configuration, wait_for_epoch_uptime};
2828
pub use request_documents::{
2929
invalid_transaction_find_document, logout_document, malformed_sasl_start_document,
3030
ping_document,

‎pg_documentdb_gw/documentdb_gateway_core/src/testing/pool.rs‎

Lines changed: 20 additions & 1 deletion

0 commit comments

Comments
 (0)