public inbox for [email protected]help / color / mirror / Atom feed
log XLogPrefetch stats at end of recovery 11+ messages / 4 participants [nested] [flat]
* log XLogPrefetch stats at end of recovery @ 2026-03-18 07:17 Lakshmi N <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Lakshmi N @ 2026-03-18 07:17 UTC (permalink / raw) To: pgsql-hackers Hi, While investigating a long recovery, I noticed that XLogPrefetch stats were not logged at the end of recovery. This log message will be useful to understand how effective XLogPrefetch was during recovery. Adding a patch to address this. Regards, Lakshmi Attachments: [application/octet-stream] 0001-log-prefetch-stats-at-end-of-recovery.patch (3.0K, 3-0001-log-prefetch-stats-at-end-of-recovery.patch) download | inline diff: From da386a487764d9bca1373c25f7b673f90f57cdba Mon Sep 17 00:00:00 2001 From: Lakshmi N <[email protected]> Date: Wed, 18 Mar 2026 00:00:51 -0700 Subject: [PATCH] log XLogPrefetch stats at end of recovery Add XLogPrefetchLogStats(), which emits a LOG message summarizing the prefetch counters (prefetch, hit, skip_init, skip_new, skip_fpw, skip_rep) accumulated during recovery. The function is called from PerformWalRecovery() immediately after the "redo done" message, giving visibility into how effective WAL prefetching was over the course of the recovery. No-op when recovery_prefetch = off. --- src/backend/access/transam/xlogprefetcher.c | 19 +++++++++++++++++++ src/backend/access/transam/xlogrecovery.c | 2 ++ src/include/access/xlogprefetcher.h | 2 ++ 3 files changed, 23 insertions(+) diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c index c235eca7c51..d9ebafe12f8 100644 --- a/src/backend/access/transam/xlogprefetcher.c +++ b/src/backend/access/transam/xlogprefetcher.c @@ -335,6 +335,25 @@ XLogPrefetchShmemInit(void) } } +/* + * Log a summary of the XLogPrefetcher stats. Intended to be called + * at the end of recovery or when a standby is promoted. + */ +void +XLogPrefetchLogStats(void) +{ + if (recovery_prefetch == RECOVERY_PREFETCH_OFF) + return; + + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", + 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)); +} + /* * 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 6d2c4a86b96..742cb90da9b 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1845,6 +1845,8 @@ PerformWalRecovery(void) errmsg("redo done at %X/%08X system usage: %s", LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), pg_rusage_show(&ru0))); + + XLogPrefetchLogStats(); xtime = GetLatestXTime(); if (xtime) ereport(LOG, diff --git a/src/include/access/xlogprefetcher.h b/src/include/access/xlogprefetcher.h index 7ec40c4b78b..a862924c895 100644 --- a/src/include/access/xlogprefetcher.h +++ b/src/include/access/xlogprefetcher.h @@ -37,6 +37,7 @@ extern void XLogPrefetchReconfigure(void); extern size_t XLogPrefetchShmemSize(void); extern void XLogPrefetchShmemInit(void); +extern void XLogPrefetchLogStats(void); extern void XLogPrefetchResetStats(void); extern XLogPrefetcher *XLogPrefetcherAllocate(XLogReaderState *reader); @@ -52,4 +53,5 @@ extern XLogRecord *XLogPrefetcherReadRecord(XLogPrefetcher *prefetcher, extern void XLogPrefetcherComputeStats(XLogPrefetcher *prefetcher); + #endif ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-21 08:15 SATYANARAYANA NARLAPURAM <[email protected]> parent: Lakshmi N <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: SATYANARAYANA NARLAPURAM @ 2026-03-21 08:15 UTC (permalink / raw) To: Lakshmi N <[email protected]>; +Cc: pgsql-hackers Hi, On Wed, Mar 18, 2026 at 12:18 AM Lakshmi N <[email protected]> wrote: > Hi, > > While investigating a long recovery, I noticed that XLogPrefetch stats > were not logged at the end of recovery. This log message will be useful to > understand how effective XLogPrefetch was during recovery. Adding a patch > to address this. > Applied this patch and validated the log message. This log message appears to be useful to me, particularly while doing fleet wide analysis. I am wondering if we can periodically log this in standby mode as well, not just before promoting? 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 Thanks, Satya ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-22 00:43 Bharath Rupireddy <[email protected]> parent: SATYANARAYANA NARLAPURAM <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Bharath Rupireddy @ 2026-03-22 00:43 UTC (permalink / raw) To: SATYANARAYANA NARLAPURAM <[email protected]>; +Cc: Lakshmi N <[email protected]>; pgsql-hackers Hi, On Sat, Mar 21, 2026 at 1:16 AM SATYANARAYANA NARLAPURAM <[email protected]> wrote: > > > While investigating a long recovery, I noticed that XLogPrefetch stats were not logged at the end of recovery. This log message will be useful to understand how effective XLogPrefetch was during recovery. Adding a patch to address this. > > Applied this patch and validated the log message. This log message appears to be useful to me, particularly while doing fleet wide analysis. > > 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 This looks useful to understand how the prefetch helped during long recoveries. > I am wondering if we can periodically log this in standby mode as well, not just before promoting? Timer-based startup progress messaging allows logging such things (ereport_startup_progress API). There was an attempt to enable "redo in progress" for standbys, but that seemed to flood the standby logs even at the default progress interval of 10 sec. Having said that, the prefetcher stats could be added to the existing ereport_startup_progress("redo in progress xxx") message that works for crash recoveries—however, I don't prefer doing a bunch of atomic reads every progress interval of 10 sec. Therefore, logging at the end of recovery looks good to me. I reviewed the patch. I have the following comment: + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", XLogPrefetcher is an internal data structure name, how about "redo prefetch stats: xxxx" to be consistent with other redo log messages? -- Bharath Rupireddy Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-23 11:29 Jakub Wartak <[email protected]> parent: Bharath Rupireddy <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Jakub Wartak @ 2026-03-23 11:29 UTC (permalink / raw) To: Bharath Rupireddy <[email protected]>; +Cc: SATYANARAYANA NARLAPURAM <[email protected]>; Lakshmi N <[email protected]>; pgsql-hackers On Sun, Mar 22, 2026 at 1:43 AM Bharath Rupireddy <[email protected]> wrote: Hi, > On Sat, Mar 21, 2026 at 1:16 AM SATYANARAYANA NARLAPURAM > <[email protected]> wrote: > > > > > While investigating a long recovery, I noticed that XLogPrefetch stats were not logged at the end of recovery. This log message will be useful to understand how effective XLogPrefetch was during recovery. Adding a patch to address this. > > > > Applied this patch and validated the log message. This log message appears to be useful to me, particularly while doing fleet wide analysis. > > > > 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 > > This looks useful to understand how the prefetch helped during long recoveries. > > > I am wondering if we can periodically log this in standby mode as well, not just before promoting? > > Timer-based startup progress messaging allows logging such things > (ereport_startup_progress API). There was an attempt to enable "redo > in progress" for standbys, but that seemed to flood the standby logs > even at the default progress interval of 10 sec. > > Having said that, the prefetcher stats could be added to the existing > ereport_startup_progress("redo in progress xxx") message that works > for crash recoveries—however, I don't prefer doing a bunch of atomic > reads every progress interval of 10 sec. > Therefore, logging at the end of recovery looks good to me. +1 from me too to only of logging at the end of recovery (so -1 to logging every now and then). If someone is interested in current state (or progress over time) I think he can query pg_stat_recovery_prefetch view already, even today, right? > I reviewed the patch. I have the following comment: > > + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, > skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", > > XLogPrefetcher is an internal data structure name, how about "redo > prefetch stats: xxxx" to be consistent with other redo log messages? +1 -J. ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-24 08:28 Lakshmi N <[email protected]> parent: Jakub Wartak <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Lakshmi N @ 2026-03-24 08:28 UTC (permalink / raw) To: Jakub Wartak <[email protected]>; +Cc: Bharath Rupireddy <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers Hi all, Thank you for your feedback. Please see the attached patch. On Mon, Mar 23, 2026 at 4:30 AM Jakub Wartak <[email protected]> wrote: > On Sun, Mar 22, 2026 at 1:43 AM Bharath Rupireddy > <[email protected]> wrote: > > Hi, > > > On Sat, Mar 21, 2026 at 1:16 AM SATYANARAYANA NARLAPURAM > > <[email protected]> wrote: > > > > > > > While investigating a long recovery, I noticed that XLogPrefetch > stats were not logged at the end of recovery. This log message will be > useful to understand how effective XLogPrefetch was during recovery. Adding > a patch to address this. > > > > > > Applied this patch and validated the log message. This log message > appears to be useful to me, particularly while doing fleet wide analysis. > > > > > > 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: > prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 > > > > This looks useful to understand how the prefetch helped during long > recoveries. > > > > > I am wondering if we can periodically log this in standby mode as > well, not just before promoting? > > > > Timer-based startup progress messaging allows logging such things > > (ereport_startup_progress API). There was an attempt to enable "redo > > in progress" for standbys, but that seemed to flood the standby logs > > even at the default progress interval of 10 sec. > > > > Having said that, the prefetcher stats could be added to the existing > > ereport_startup_progress("redo in progress xxx") message that works > > for crash recoveries—however, I don't prefer doing a bunch of atomic > > reads every progress interval of 10 sec. > > > Therefore, logging at the end of recovery looks good to me. > > +1 from me too to only of logging at the end of recovery (so -1 to logging > every now and then). If someone is interested in current state (or progress > over time) I think he can query pg_stat_recovery_prefetch view already, > even > today, right? > I reviewed the patch. I have the following comment: > > > > + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, > > skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", > > > > XLogPrefetcher is an internal data structure name, how about "redo > > prefetch stats: xxxx" to be consistent with other redo log messages? > > +1 > please find the attached patch addressing this. Regards, Lakshmi Attachments: [application/octet-stream] 0001-log-prefetch-stats-at-end-of-recovery.patch (3.0K, 3-0001-log-prefetch-stats-at-end-of-recovery.patch) download | inline diff: From adc40191fb39bea3ae4d02d5573f50144844e94d Mon Sep 17 00:00:00 2001 From: Lakshmi N <[email protected]> Date: Tue, 24 Mar 2026 01:23:24 -0700 Subject: [PATCH] xlogprefetcher: log prefetch statistics at end of recovery Add XLogPrefetchLogStats(), which emits a LOG message summarising the prefetch counters (prefetch, hit, skip_init, skip_new, skip_fpw, skip_rep) accumulated during recovery. The function is called from PerformWalRecovery() immediately after the "redo done" message, giving operators visibility into how effective WAL prefetching was over the course of the recovery session. No-op when recovery_prefetch = off. --- src/backend/access/transam/xlogprefetcher.c | 19 +++++++++++++++++++ src/backend/access/transam/xlogrecovery.c | 2 ++ src/include/access/xlogprefetcher.h | 2 ++ 3 files changed, 23 insertions(+) diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c index c235eca7c51..49acb36af1c 100644 --- a/src/backend/access/transam/xlogprefetcher.c +++ b/src/backend/access/transam/xlogprefetcher.c @@ -335,6 +335,25 @@ XLogPrefetchShmemInit(void) } } +/* + * Log a summary of the XLogPrefetcher stats. Intended to be called + * at the end of recovery or when a standby is promoted. + */ +void +XLogPrefetchLogStats(void) +{ + if (recovery_prefetch == RECOVERY_PREFETCH_OFF) + return; + + elog(LOG, "redo prefetch stats: prefetch=%lu, hit=%lu, skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", + 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)); +} + /* * 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 6d2c4a86b96..742cb90da9b 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1845,6 +1845,8 @@ PerformWalRecovery(void) errmsg("redo done at %X/%08X system usage: %s", LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), pg_rusage_show(&ru0))); + + XLogPrefetchLogStats(); xtime = GetLatestXTime(); if (xtime) ereport(LOG, diff --git a/src/include/access/xlogprefetcher.h b/src/include/access/xlogprefetcher.h index 7ec40c4b78b..a862924c895 100644 --- a/src/include/access/xlogprefetcher.h +++ b/src/include/access/xlogprefetcher.h @@ -37,6 +37,7 @@ extern void XLogPrefetchReconfigure(void); extern size_t XLogPrefetchShmemSize(void); extern void XLogPrefetchShmemInit(void); +extern void XLogPrefetchLogStats(void); extern void XLogPrefetchResetStats(void); extern XLogPrefetcher *XLogPrefetcherAllocate(XLogReaderState *reader); @@ -52,4 +53,5 @@ extern XLogRecord *XLogPrefetcherReadRecord(XLogPrefetcher *prefetcher, extern void XLogPrefetcherComputeStats(XLogPrefetcher *prefetcher); + #endif -- 2.43.0 ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-24 08:53 Jakub Wartak <[email protected]> parent: Lakshmi N <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Jakub Wartak @ 2026-03-24 08:53 UTC (permalink / raw) To: Lakshmi N <[email protected]>; Thomas Munro <[email protected]>; +Cc: Bharath Rupireddy <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers On Tue, Mar 24, 2026 at 9:28 AM Lakshmi N <[email protected]> wrote: > > Hi all, > > Thank you for your feedback. Please see the attached patch. > > On Mon, Mar 23, 2026 at 4:30 AM Jakub Wartak <[email protected]> wrote: >> >> On Sun, Mar 22, 2026 at 1:43 AM Bharath Rupireddy >> <[email protected]> wrote: >> >> Hi, >> >> > On Sat, Mar 21, 2026 at 1:16 AM SATYANARAYANA NARLAPURAM >> > <[email protected]> wrote: >> > > >> > > > While investigating a long recovery, I noticed that XLogPrefetch stats were not logged at the end of recovery. This log message will be useful to understand how effective XLogPrefetch was during recovery. Adding a patch to address this. >> > > >> > > Applied this patch and validated the log message. This log message appears to be useful to me, particularly while doing fleet wide analysis. >> > > >> > > 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 >> > >> > This looks useful to understand how the prefetch helped during long recoveries. >> > >> > > I am wondering if we can periodically log this in standby mode as well, not just before promoting? >> > >> > Timer-based startup progress messaging allows logging such things >> > (ereport_startup_progress API). There was an attempt to enable "redo >> > in progress" for standbys, but that seemed to flood the standby logs >> > even at the default progress interval of 10 sec. >> > >> > Having said that, the prefetcher stats could be added to the existing >> > ereport_startup_progress("redo in progress xxx") message that works >> > for crash recoveries—however, I don't prefer doing a bunch of atomic >> > reads every progress interval of 10 sec. >> >> > Therefore, logging at the end of recovery looks good to me. >> >> +1 from me too to only of logging at the end of recovery (so -1 to logging >> every now and then). If someone is interested in current state (or progress >> over time) I think he can query pg_stat_recovery_prefetch view already, even >> today, right? >> >> > I reviewed the patch. I have the following comment: >> > >> > + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, >> > skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", >> > >> > XLogPrefetcher is an internal data structure name, how about "redo >> > prefetch stats: xxxx" to be consistent with other redo log messages? >> >> +1 > > > please find the attached patch addressing this. Hi Lakshmi, The pg_stat_get_recovery_prefetch view has 3 additional columns, but they are showing current situation, maybe this $patch could be enhanced so that it also calculates averages for some of them? I mean perhaps not just hit ratio would be nice, but also the e.g. __average__ wal distance or average look ahead (block distance). I'm not sure maybe please also wait for input from others if they find it a good idea or not. Also if we are adding such pretty cryptic fields as "skip_fpw" to log, we would need some place in documentaiton to explain their meaining probably. monitoring.sgml already explains them, so maybe just link to that. I mean if you look what we have today (below), they are little less crypting and have different format, not "skip_fpw=123" but more like "17 removed" so maybe "17 skipped due to FPW". Maybe redo done at 0/75C7B290 system usage: CPU: user: 1.02 s, system: 0.51 s, elapsed: 1.53 s checkpoint complete: end-of-recovery fast wait: wrote 16289 buffers (99.4%), wrote 3 SLRU buffers; 0 WAL file(s) added, 17 removed, 0 recycled; write=0.049 s, sync=0.191 s, total=0.264 s; sync files=10, longest=0.187 s, average=0.020 s; distance=287186 kB, estimate=287186 kB; lsn=0/75C7B2C8, redo lsn=0/75C7B2C8 so instead of like: redo prefetch stats: prefetch=%lu, hit=%lu, skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu" something like below ones: redo prefetch stats: done %lu prefetches, %lu hit, %lu zero-initated, .. redo prefetch stats: done %lu prefetches, (%d% hit ratio), %lu zero-initated, .. or something like that -J. ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-24 12:07 Lakshmi N <[email protected]> parent: Jakub Wartak <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Lakshmi N @ 2026-03-24 12:07 UTC (permalink / raw) To: Jakub Wartak <[email protected]>; +Cc: Thomas Munro <[email protected]>; Bharath Rupireddy <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers Hi, On Tue, Mar 24, 2026 at 1:53 AM Jakub Wartak <[email protected]> wrote: > On Tue, Mar 24, 2026 at 9:28 AM Lakshmi N <[email protected]> wrote: > > > > Hi all, > > > > Thank you for your feedback. Please see the attached patch. > > > > On Mon, Mar 23, 2026 at 4:30 AM Jakub Wartak < > [email protected]> wrote: > >> > >> On Sun, Mar 22, 2026 at 1:43 AM Bharath Rupireddy > >> <[email protected]> wrote: > >> > >> Hi, > >> > >> > On Sat, Mar 21, 2026 at 1:16 AM SATYANARAYANA NARLAPURAM > >> > <[email protected]> wrote: > >> > > > >> > > > While investigating a long recovery, I noticed that XLogPrefetch > stats were not logged at the end of recovery. This log message will be > useful to understand how effective XLogPrefetch was during recovery. Adding > a patch to address this. > >> > > > >> > > Applied this patch and validated the log message. This log message > appears to be useful to me, particularly while doing fleet wide analysis. > >> > > > >> > > 2026-03-20 23:33:13.756 PDT [2265441] LOG: XLogPrefetcher stats: > prefetch=14, hit=6, skip_init=5, skip_new=28, skip_fpw=18, skip_rep=996 > >> > > >> > This looks useful to understand how the prefetch helped during long > recoveries. > >> > > >> > > I am wondering if we can periodically log this in standby mode as > well, not just before promoting? > >> > > >> > Timer-based startup progress messaging allows logging such things > >> > (ereport_startup_progress API). There was an attempt to enable "redo > >> > in progress" for standbys, but that seemed to flood the standby logs > >> > even at the default progress interval of 10 sec. > >> > > >> > Having said that, the prefetcher stats could be added to the existing > >> > ereport_startup_progress("redo in progress xxx") message that works > >> > for crash recoveries—however, I don't prefer doing a bunch of atomic > >> > reads every progress interval of 10 sec. > >> > >> > Therefore, logging at the end of recovery looks good to me. > >> > >> +1 from me too to only of logging at the end of recovery (so -1 to > logging > >> every now and then). If someone is interested in current state (or > progress > >> over time) I think he can query pg_stat_recovery_prefetch view already, > even > >> today, right? > >> > >> > I reviewed the patch. I have the following comment: > >> > > >> > + elog(LOG, "XLogPrefetcher stats: prefetch=%lu, hit=%lu, > >> > skip_init=%lu, skip_new=%lu, skip_fpw=%lu, skip_rep=%lu", > >> > > >> > XLogPrefetcher is an internal data structure name, how about "redo > >> > prefetch stats: xxxx" to be consistent with other redo log messages? > >> > >> +1 > > > > > > please find the attached patch addressing this. > > Hi Lakshmi, > > The pg_stat_get_recovery_prefetch view has 3 additional columns, but they > are > showing current situation, maybe this $patch could be enhanced so that it > also > calculates averages for some of them? I mean perhaps not just hit ratio > would be > nice, but also the e.g. __average__ wal distance or average look ahead > (block distance). > I'm not sure maybe please also wait for input from others if they find > it a good idea > or not. > > Also if we are adding such pretty cryptic fields as "skip_fpw" to log, > we would need some > place in documentaiton to explain their meaining probably. > monitoring.sgml already > explains them, so maybe just link to that. I mean if you look what we > have today (below), > they are little less crypting and have different format, not > "skip_fpw=123" but more > like "17 removed" so maybe "17 skipped due to FPW". Maybe > > redo done at 0/75C7B290 system usage: CPU: user: 1.02 s, system: 0.51 > s, elapsed: 1.53 s > checkpoint complete: end-of-recovery fast wait: wrote 16289 buffers > (99.4%), wrote 3 SLRU buffers; 0 WAL file(s) added, 17 removed, 0 > recycled; write=0.049 s, sync=0.191 s, total=0.264 s; sync files=10, > longest=0.187 s, average=0.020 s; distance=287186 kB, estimate=287186 > kB; lsn=0/75C7B2C8, redo lsn=0/75C7B2C8 > > so instead of like: > redo prefetch stats: prefetch=%lu, hit=%lu, skip_init=%lu, > skip_new=%lu, skip_fpw=%lu, skip_rep=%lu" > > something like below ones: > redo prefetch stats: done %lu prefetches, %lu hit, %lu zero-initated, .. > redo prefetch stats: done %lu prefetches, (%d% hit ratio), %lu > zero-initated, .. or something like that > Please find the attached patch with the suggested changes. I referenced [1] to log the message as suggested. 2026-03-24 04:53:15.251 PDT [18898] LOG: redo prefetch stats: prefetched 27 blocks, skipped 22 blocks because they were already in the buffer pool, skipped 17 blocks because they would be zero-initialized, skipped 0 blocks because they didn't exist yet, skipped 28 blocks because a full page image was included in the WAL, skipped 155 blocks because they were already recently prefetched. [1] https://www.postgresql.org/docs/devel/monitoring-stats.html#MONITORING-PG-STAT-RECOVERY-PREFETCH Regards, Lakshmi Attachments: [application/octet-stream] 0001-log-prefetch-stats-at-end-of-recovery.patch (3.3K, 3-0001-log-prefetch-stats-at-end-of-recovery.patch) download | inline diff: From 6c29ac6ac297014fceb2e02bd15c53ee463ac281 Mon Sep 17 00:00:00 2001 From: Lakshmi N <[email protected]> Date: Tue, 24 Mar 2026 01:23:24 -0700 Subject: [PATCH] xlogprefetcher: log prefetch statistics at end of recovery Add XLogPrefetchLogStats(), which emits a LOG message summarising the prefetch counters (prefetch, hit, skip_init, skip_new, skip_fpw, skip_rep) accumulated during recovery. The function is called from PerformWalRecovery() immediately after the "redo done" message, giving operators visibility into how effective WAL prefetching was over the course of the recovery session. No-op when recovery_prefetch = off. --- src/backend/access/transam/xlogprefetcher.c | 25 +++++++++++++++++++++ src/backend/access/transam/xlogrecovery.c | 2 ++ src/include/access/xlogprefetcher.h | 2 ++ 3 files changed, 29 insertions(+) diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c index c235eca7c51..76be0cc1bcf 100644 --- a/src/backend/access/transam/xlogprefetcher.c +++ b/src/backend/access/transam/xlogprefetcher.c @@ -335,6 +335,31 @@ XLogPrefetchShmemInit(void) } } +/* + * Log a summary of the XLogPrefetcher stats. Intended to be called + * at the end of recovery or when a standby is promoted. + */ +void +XLogPrefetchLogStats(void) +{ + if (recovery_prefetch == RECOVERY_PREFETCH_OFF) + return; + + elog(LOG, + "redo prefetch stats: prefetched %lu blocks, " + "skipped %lu blocks because they were already in the buffer pool, " + "skipped %lu blocks because they would be zero-initialized, " + "skipped %lu blocks because they didn't exist yet, " + "skipped %lu blocks because a full page image was included in the WAL, " + "skipped %lu blocks because they were already 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)); +} + /* * 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 6d2c4a86b96..742cb90da9b 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1845,6 +1845,8 @@ PerformWalRecovery(void) errmsg("redo done at %X/%08X system usage: %s", LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), pg_rusage_show(&ru0))); + + XLogPrefetchLogStats(); xtime = GetLatestXTime(); if (xtime) ereport(LOG, diff --git a/src/include/access/xlogprefetcher.h b/src/include/access/xlogprefetcher.h index 7ec40c4b78b..a862924c895 100644 --- a/src/include/access/xlogprefetcher.h +++ b/src/include/access/xlogprefetcher.h @@ -37,6 +37,7 @@ extern void XLogPrefetchReconfigure(void); extern size_t XLogPrefetchShmemSize(void); extern void XLogPrefetchShmemInit(void); +extern void XLogPrefetchLogStats(void); extern void XLogPrefetchResetStats(void); extern XLogPrefetcher *XLogPrefetcherAllocate(XLogReaderState *reader); @@ -52,4 +53,5 @@ extern XLogRecord *XLogPrefetcherReadRecord(XLogPrefetcher *prefetcher, extern void XLogPrefetcherComputeStats(XLogPrefetcher *prefetcher); + #endif -- 2.43.0 ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-25 03:23 Bharath Rupireddy <[email protected]> parent: Lakshmi N <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Bharath Rupireddy @ 2026-03-25 03:23 UTC (permalink / raw) To: Lakshmi N <[email protected]>; +Cc: Jakub Wartak <[email protected]>; Thomas Munro <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers Hi, On Tue, Mar 24, 2026 at 5:07 AM Lakshmi N <[email protected]> wrote: > >> so instead of like: >> redo prefetch stats: prefetch=%lu, hit=%lu, skip_init=%lu, >> skip_new=%lu, skip_fpw=%lu, skip_rep=%lu" >> >> something like below ones: >> redo prefetch stats: done %lu prefetches, %lu hit, %lu zero-initated, .. >> redo prefetch stats: done %lu prefetches, (%d% hit ratio), %lu >> zero-initated, .. or something like that > > Please find the attached patch with the suggested changes. I referenced [1] to log the message as suggested. > > 2026-03-24 04:53:15.251 PDT [18898] LOG: redo prefetch stats: prefetched 27 blocks, skipped 22 blocks because they were already in the buffer pool, skipped 17 blocks because they would be zero-initialized, skipped 0 blocks because they didn't exist yet, skipped 28 blocks because a full page image was included in the WAL, skipped 155 blocks because they were already recently prefetched. IMHO, the above looks too verbose. +1 for Jakub's suggestion. Would something like the below work? I believe the developers looking at these logs for analysis will have some understanding of what each of these means. LOG: redo prefetch stats: prefetched 27, skipped (22 in buffer pool, 17 zero-inited, 0 non-existent, 28 FPI, 155 recently prefetched) -- Bharath Rupireddy Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-26 08:06 Lakshmi N <[email protected]> parent: Bharath Rupireddy <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Lakshmi N @ 2026-03-26 08:06 UTC (permalink / raw) To: Bharath Rupireddy <[email protected]>; +Cc: Jakub Wartak <[email protected]>; Thomas Munro <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers Hi, On Tue, Mar 24, 2026 at 8:23 PM Bharath Rupireddy < [email protected]> wrote: > Hi, > > On Tue, Mar 24, 2026 at 5:07 AM Lakshmi N <[email protected]> wrote: > > > >> so instead of like: > >> redo prefetch stats: prefetch=%lu, hit=%lu, skip_init=%lu, > >> skip_new=%lu, skip_fpw=%lu, skip_rep=%lu" > >> > >> something like below ones: > >> redo prefetch stats: done %lu prefetches, %lu hit, %lu zero-initated, .. > >> redo prefetch stats: done %lu prefetches, (%d% hit ratio), %lu > >> zero-initated, .. or something like that > > > > Please find the attached patch with the suggested changes. I referenced > [1] to log the message as suggested. > > > > 2026-03-24 04:53:15.251 PDT [18898] LOG: redo prefetch stats: > prefetched 27 blocks, skipped 22 blocks because they were already in the > buffer pool, skipped 17 blocks because they would be zero-initialized, > skipped 0 blocks because they didn't exist yet, skipped 28 blocks because a > full page image was included in the WAL, skipped 155 blocks because they > were already recently prefetched. > > IMHO, the above looks too verbose. +1 for Jakub's suggestion. Would > something like the below work? I believe the developers looking at > these logs for analysis will have some understanding of what each of > these means. > > LOG: redo prefetch stats: prefetched 27, skipped (22 in buffer pool, > 17 zero-inited, 0 non-existent, 28 FPI, 155 recently prefetched) > Address this in the attached patch. Please let me know if this looks good. 2026-03-26 00:51:19.797 PDT [91881] LOG: redo prefetch stats: prefetched 418376 blocks, skipped (362419 in the buffer pool, 418479 zero-initialized, 0 non-existent, 9 full page image, 39183318 recently prefetched) Regards, Lakshmi Attachments: [application/octet-stream] v3-0001-xlogprefetcher-redo-stats-logging.patch (2.9K, 3-v3-0001-xlogprefetcher-redo-stats-logging.patch) download | inline diff: From 64c96c20bb7345aad3dc6d3a1c2e9410b47ffdee Mon Sep 17 00:00:00 2001 From: Lakshmi N <[email protected]> Date: Thu, 26 Mar 2026 01:02:57 -0700 Subject: [PATCH] xlogprefetcher: Log prefetch statistics at end of recovery Add XLogPrefetchLogStats(), which emits a LOG message summarising the prefetch counters (prefetch, hit, skip_init, skip_new, skip_fpw, skip_rep) accumulated during recovery. The function is called from PerformWalRecovery() immediately after the "redo done" message, giving operators visibility into how effective WAL prefetching was over the course of the recovery session. No-op when recovery_prefetch = off. --- src/backend/access/transam/xlogprefetcher.c | 25 +++++++++++++++++++++ src/backend/access/transam/xlogrecovery.c | 2 ++ src/include/access/xlogprefetcher.h | 1 + 3 files changed, 28 insertions(+) diff --git a/src/backend/access/transam/xlogprefetcher.c b/src/backend/access/transam/xlogprefetcher.c index c235eca7c51..879e6591c20 100644 --- a/src/backend/access/transam/xlogprefetcher.c +++ b/src/backend/access/transam/xlogprefetcher.c @@ -335,6 +335,31 @@ XLogPrefetchShmemInit(void) } } +/* + * Log a summary of the XLogPrefetcher stats. Intended to be called + * at the end of recovery or when a standby is promoted. + */ +void +XLogPrefetchLogStats(void) +{ + if (recovery_prefetch == RECOVERY_PREFETCH_OFF) + return; + + elog(LOG, + "redo prefetch stats: prefetched %lu blocks, " + "skipped (%lu in the buffer pool, " + "%lu zero-initialized, " + "%lu non-existent, " + "%lu full page image, " + "%lu 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)); +} + /* * 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 6d2c4a86b96..7e5482fd976 100644 --- a/src/backend/access/transam/xlogrecovery.c +++ b/src/backend/access/transam/xlogrecovery.c @@ -1845,6 +1845,8 @@ PerformWalRecovery(void) errmsg("redo done at %X/%08X system usage: %s", LSN_FORMAT_ARGS(xlogreader->ReadRecPtr), pg_rusage_show(&ru0))); + + XLogPrefetchLogStats(); xtime = GetLatestXTime(); if (xtime) ereport(LOG, diff --git a/src/include/access/xlogprefetcher.h b/src/include/access/xlogprefetcher.h index 7ec40c4b78b..5f9f48980cd 100644 --- a/src/include/access/xlogprefetcher.h +++ b/src/include/access/xlogprefetcher.h @@ -37,6 +37,7 @@ extern void XLogPrefetchReconfigure(void); extern size_t XLogPrefetchShmemSize(void); extern void XLogPrefetchShmemInit(void); +extern void XLogPrefetchLogStats(void); extern void XLogPrefetchResetStats(void); extern XLogPrefetcher *XLogPrefetcherAllocate(XLogReaderState *reader); -- 2.43.0 ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-27 00:10 Bharath Rupireddy <[email protected]> parent: Lakshmi N <[email protected]> 0 siblings, 1 reply; 11+ messages in thread From: Bharath Rupireddy @ 2026-03-27 00:10 UTC (permalink / raw) To: Lakshmi N <[email protected]>; +Cc: Jakub Wartak <[email protected]>; Thomas Munro <[email protected]>; SATYANARAYANA NARLAPURAM <[email protected]>; pgsql-hackers Hi, On Thu, Mar 26, 2026 at 1:06 AM Lakshmi N <[email protected]> wrote: > > Address this in the attached patch. Please let me know if this looks good. > 2026-03-26 00:51:19.797 PDT [91881] LOG: redo prefetch stats: prefetched 418376 blocks, skipped (362419 in the buffer pool, 418479 zero-initialized, 0 non-existent, 9 full page image, 39183318 recently prefetched) Thanks for sending the latest patch. It looks good to me with a nit:s/362419 in the buffer pool/362419 already in buffer pool. I will leave it to others' choice. -- Bharath Rupireddy Amazon Web Services: https://aws.amazon.com ^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: log XLogPrefetch stats at end of recovery @ 2026-03-28 05:08 SATYANARAYANA NARLAPURAM <[email protected]> parent: Bharath Rupireddy <[email protected]> 0 siblings, 0 replies; 11+ messages in thread From: SATYANARAYANA NARLAPURAM @ 2026-03-28 05:08 UTC (permalink / raw) To: Bharath Rupireddy <[email protected]>; +Cc: Lakshmi N <[email protected]>; Jakub Wartak <[email protected]>; Thomas Munro <[email protected]>; pgsql-hackers On Thu, Mar 26, 2026 at 5:10 PM Bharath Rupireddy < [email protected]> wrote: > Hi, > > On Thu, Mar 26, 2026 at 1:06 AM Lakshmi N <[email protected]> wrote: > > > > Address this in the attached patch. Please let me know if this looks > good. > > 2026-03-26 00:51:19.797 PDT [91881] LOG: redo prefetch stats: > prefetched 418376 blocks, skipped (362419 in the buffer pool, 418479 > zero-initialized, 0 non-existent, 9 full page image, 39183318 recently > prefetched) > > Thanks for sending the latest patch. It looks good to me with a > nit:s/362419 in the buffer pool/362419 already in buffer pool. I will > leave it to others' choice LGTM too, I will leave it to the committer's choice. Thanks, Satya ^ permalink raw reply [nested|flat] 11+ messages in thread
end of thread, other threads:[~2026-03-28 05:08 UTC | newest] Thread overview: 11+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2026-03-18 07:17 log XLogPrefetch stats at end of recovery Lakshmi N <[email protected]> 2026-03-21 08:15 ` SATYANARAYANA NARLAPURAM <[email protected]> 2026-03-22 00:43 ` Bharath Rupireddy <[email protected]> 2026-03-23 11:29 ` Jakub Wartak <[email protected]> 2026-03-24 08:28 ` Lakshmi N <[email protected]> 2026-03-24 08:53 ` Jakub Wartak <[email protected]> 2026-03-24 12:07 ` Lakshmi N <[email protected]> 2026-03-25 03:23 ` Bharath Rupireddy <[email protected]> 2026-03-26 08:06 ` Lakshmi N <[email protected]> 2026-03-27 00:10 ` Bharath Rupireddy <[email protected]> 2026-03-28 05:08 ` SATYANARAYANA NARLAPURAM <[email protected]>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox