From 0a1cdacf2cc875890ee745fa3eb0ae68b748f35e Mon Sep 17 00:00:00 2001 From: Ashutosh Sharma Date: Fri, 6 Nov 2026 06:48:49 +0000 Subject: [PATCH] xlogprefetcher: Log prefetch statistics at end of recovery Add XLogPrefetchLogStatsOnRecoveryEnd() to log the accumulated prefetch counters immediately after the "redo done" message in PerformWalRecovery(). This gives operators visibility into WAL prefetching activity during recovery. Log the counters even when prefetching is disabled at recovery completion or all counters are zero, so that disabling prefetching during recovery does not suppress statistics already collected. Include the current recovery_prefetch setting in the message detail. The counters reflect activity since the last statistics reset, so a reset during recovery excludes earlier activity from the summary. Add recovery tests covering zero counters and statistics retained after disabling prefetching. Author: Lakshmi N Co-authored-by: Ashutosh Sharma Reviewed-by: Bharath Rupireddy Discussion: https://www.postgresql.org/message-id/CA%2B3i_M-%2BWVyrRcfnxa4gt%2BKQUzH-LTQ8D2JCGE_O0WzJJtZfUg%40mail.gmail.com --- src/backend/access/transam/xlogprefetcher.c | 18 ++++++ src/backend/access/transam/xlogrecovery.c | 3 + src/include/access/xlogprefetcher.h | 1 + src/test/recovery/meson.build | 1 + src/test/recovery/t/061_prefetch_stats.pl | 69 +++++++++++++++++++++ 5 files changed, 92 insertions(+) create mode 100644 src/test/recovery/t/061_prefetch_stats.pl diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c index 288cdbd34c4..6669dd04bf6 100644 --- a/src/backend/access/transam/xlogprefetcher.c +++ b/src/backend/access/transam/xlogprefetcher.c @@ -41,6 +41,7 @@ #include "storage/smgr.h" #include "storage/subsystems.h" #include "utils/fmgrprotos.h" +#include "utils/guc.h" #include "utils/guc_hooks.h" #include "utils/hsearch.h" #include "utils/timestamp.h" @@ -337,6 +338,23 @@ XLogPrefetchResetStats(void) pg_atomic_write_u64(&SharedStats->skip_rep, 0); } +/* + * Log a summary of the prefetch counters at the end of recovery. + */ +void +XLogPrefetchLogStatsOnRecoveryEnd(void) +{ + ereport(LOG, + errmsg("redo prefetch stats: prefetched %" PRIu64 " blocks, skipped (%" PRIu64 " in the buffer pool, %" PRIu64 " zero-initialized, %" PRIu64 " non-existent, %" PRIu64 " full page image, %" PRIu64 " recently prefetched)", + pg_atomic_read_u64(&SharedStats->prefetch), + pg_atomic_read_u64(&SharedStats->hit), + pg_atomic_read_u64(&SharedStats->skip_init), + pg_atomic_read_u64(&SharedStats->skip_new), + pg_atomic_read_u64(&SharedStats->skip_fpw), + pg_atomic_read_u64(&SharedStats->skip_rep)), + errdetail("recovery_prefetch = %s at the end of recovery.", + GetConfigOption("recovery_prefetch", false, false))); +} /* * Called when any GUC is changed that affects prefetching. diff --git a/src/backend/access/transam/xlogrecovery.c b/src/backend/access/transam/xlogrecovery.c index 52ac6d58423..503cf3960e7 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1872,6 +1872,9 @@ PerformWalRecovery(void) errmsg("redo done at %X/%08X system usage: %s", LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), pg_rusage_show(&ru0))); + + XLogPrefetchLogStatsOnRecoveryEnd(); + xtime = GetLatestXTime(); if (xtime) ereport(LOG, diff --git a/src/include/access/xlogprefetcher.h b/src/include/access/xlogprefetcher.h index 56a81676d92..65d0ac6397d 100644 --- a/src/include/access/xlogprefetcher.h +++ b/src/include/access/xlogprefetcher.h @@ -34,6 +34,7 @@ typedef struct XLogPrefetcher XLogPrefetcher; extern void XLogPrefetchReconfigure(void); +extern void XLogPrefetchLogStatsOnRecoveryEnd(void); extern void XLogPrefetchResetStats(void); extern XLogPrefetcher *XLogPrefetcherAllocate(XLogReaderState *reader); diff --git a/src/test/recovery/meson.build b/src/test/recovery/meson.build index b6ac9dd07a7..0bb13ba95b6 100644 --- a/src/test/recovery/meson.build +++ b/src/test/recovery/meson.build @@ -69,6 +69,7 @@ tests += { 't/058_shutdown_crash_restart.pl', 't/059_remote_apply_status_interval.pl', 't/060_multixact_crashed_updater.pl', + 't/061_prefetch_stats.pl', ], }, } diff --git a/src/test/recovery/t/061_prefetch_stats.pl b/src/test/recovery/t/061_prefetch_stats.pl new file mode 100644 index 00000000000..b69e634fe66 --- /dev/null +++ b/src/test/recovery/t/061_prefetch_stats.pl @@ -0,0 +1,69 @@ +# Copyright (c) 2026, PostgreSQL Global Development Group + +use strict; +use warnings FATAL => 'all'; +use PostgreSQL::Test::Cluster; +use PostgreSQL::Test::Utils; +use Test::More; + +my $primary = PostgreSQL::Test::Cluster->new('primary'); +$primary->init(allows_streaming => 1); +$primary->start; +$primary->backup('backup'); + +my @counters = qw(prefetch hit skip_init skip_new skip_fpw skip_rep); +my $counter_query = + 'SELECT ' . join(', ', @counters) . ' FROM pg_stat_recovery_prefetch'; + +for my $mode ('off', 'try') +{ + my $standby = PostgreSQL::Test::Cluster->new("standby_$mode"); + $standby->init_from_backup($primary, 'backup', has_streaming => 1); + $standby->append_conf( + 'postgresql.conf', + "recovery_prefetch = '$mode'\nmaintenance_io_concurrency = 10"); + $standby->start; + + $primary->safe_psql('postgres', + "CREATE TABLE tab_$mode AS SELECT generate_series(1, 10000) AS a"); + $primary->wait_for_replay_catchup($standby); + + my @values = split /\|/, $standby->safe_psql('postgres', $counter_query); + if ($mode eq 'off') + { + is(join('|', @values), '0|0|0|0|0|0', + 'prefetch counters are zero when disabled throughout recovery'); + } + else + { + # Retain counters collected before prefetching was disabled. + $standby->safe_psql('postgres', + "ALTER SYSTEM SET recovery_prefetch = 'off'"); + $standby->reload; + ok( $standby->poll_query_until( + 'postgres', "SHOW recovery_prefetch", 'off'), + 'prefetching is disabled before promotion'); + $primary->safe_psql('postgres', "INSERT INTO tab_try VALUES (10001)"); + $primary->wait_for_replay_catchup($standby); + is($standby->safe_psql('postgres', $counter_query), + join('|', @values), + 'disabling prefetching preserves accumulated counters'); + } + + my $offset = -s $standby->logfile; + $standby->promote; + $standby->log_check( + "prefetch summary after recovery with initial setting $mode", + $offset, + log_like => [ + qr/LOG: redo prefetch stats: prefetched $values[0] blocks, skipped \($values[1] in the buffer pool, $values[2] zero-initialized, $values[3] non-existent, $values[4] full page image, $values[5] recently prefetched\)/, + qr/DETAIL: recovery_prefetch = off at the end of recovery\./ + ]); + my $log = slurp_file($standby->logfile, $offset); + is(scalar(() = $log =~ /LOG: redo prefetch stats:/g), + 1, 'one prefetch summary is logged at recovery completion'); + $standby->stop; +} + +$primary->stop; +done_testing(); -- 2.43.0