MIME-Version: 1.0
References: 
 <CA+3i_M-+WVyrRcfnxa4gt+KQUzH-LTQ8D2JCGE_O0WzJJtZfUg@mail.gmail.com>
 <CAHg+QDfLh-yb+OacN6qPYF6H3SPDmVJUiors7vkSMq4yxfhNrA@mail.gmail.com>
 <CALj2ACWovfe_A43LP5fi0mJenZ-i99_ux68YCzX6D2CO5mB-gg@mail.gmail.com>
 <CAKZiRmwuKVHaQa_3PirbBqzoCKciuqcn2Tn4Df4d8icq4e3DCA@mail.gmail.com>
 <CA+3i_M9s6T-jOsvSZk5y1HVvyz_RVbiEQZGdwPRQrw+zZcZ5Eg@mail.gmail.com>
In-Reply-To: 
 <CA+3i_M9s6T-jOsvSZk5y1HVvyz_RVbiEQZGdwPRQrw+zZcZ5Eg@mail.gmail.com>
From: Jakub Wartak <jakub.wartak@enterprisedb.com>
Date: Tue, 24 Mar 2026 09:53:44 +0100
Message-ID: 
 <CAKZiRmz3n24HZVzQX4=25y4tMZ9PjYQjmbGhJkrziAQjdHru5g@mail.gmail.com>
Subject: Re: log XLogPrefetch stats at end of recovery
To: Lakshmi N <lakshmin.jhs@gmail.com>, Thomas Munro <thomas.munro@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>,
	SATYANARAYANA NARLAPURAM <satyanarlapuram@gmail.com>,
 pgsql-hackers@postgresql.org
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Archived-At: 
 <https://www.postgresql.org/message-id/CAKZiRmz3n24HZVzQX4%3D25y4tMZ9PjYQjmbGhJkrziAQjdHru5g%40mail.gmail.com>
Precedence: bulk

On Tue, Mar 24, 2026 at 9:28=E2=80=AFAM Lakshmi N <lakshmin.jhs@gmail.com> =
wrote:
>
> Hi all,
>
> Thank you for your feedback. Please see the attached patch.
>
> On Mon, Mar 23, 2026 at 4:30=E2=80=AFAM Jakub Wartak <jakub.wartak@enterp=
risedb.com> wrote:
>>
>> On Sun, Mar 22, 2026 at 1:43=E2=80=AFAM Bharath Rupireddy
>> <bharath.rupireddyforpostgres@gmail.com> wrote:
>>
>> Hi,
>>
>> > On Sat, Mar 21, 2026 at 1:16=E2=80=AFAM SATYANARAYANA NARLAPURAM
>> > <satyanarlapuram@gmail.com> wrote:
>> > >
>> > > > While investigating a long recovery, I noticed that XLogPrefetch s=
tats were not logged at the end of recovery. This log message will be usefu=
l to understand how effective XLogPrefetch was during recovery. Adding a pa=
tch to address this.
>> > >
>> > > Applied this patch and validated the log message. This log message a=
ppears to be useful to me, particularly while doing fleet wide analysis.
>> > >
>> > > 2026-03-20 23:33:13.756 PDT [2265441] LOG:  XLogPrefetcher stats: pr=
efetch=3D14, hit=3D6, skip_init=3D5, skip_new=3D28, skip_fpw=3D18, skip_rep=
=3D996
>> >
>> > This looks useful to understand how the prefetch helped during long re=
coveries.
>> >
>> > > I am wondering if we can periodically log this in standby mode as we=
ll, 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=E2=80=94however, 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 loggi=
ng
>> every now and then). If someone is interested in current state (or progr=
ess
>> 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=3D%lu, hit=3D%lu,
>> > skip_init=3D%lu, skip_new=3D%lu, skip_fpw=3D%lu, skip_rep=3D%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 a=
re
showing current situation, maybe this $patch could be enhanced so that it a=
lso
calculates averages for some of them? I mean perhaps not just hit ratio wou=
ld 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=3D123" 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=3D0.049 s, sync=3D0.191 s, total=3D0.264 s; sync files=3D10=
,
longest=3D0.187 s, average=3D0.020 s; distance=3D287186 kB, estimate=3D2871=
86
kB; lsn=3D0/75C7B2C8, redo lsn=3D0/75C7B2C8

so instead of like:
redo prefetch stats: prefetch=3D%lu, hit=3D%lu, skip_init=3D%lu,
skip_new=3D%lu, skip_fpw=3D%lu, skip_rep=3D%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.