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>
In-Reply-To: 
 <CAKZiRmwuKVHaQa_3PirbBqzoCKciuqcn2Tn4Df4d8icq4e3DCA@mail.gmail.com>
From: Lakshmi N <lakshmin.jhs@gmail.com>
Date: Tue, 24 Mar 2026 01:28:13 -0700
Message-ID: 
 <CA+3i_M9s6T-jOsvSZk5y1HVvyz_RVbiEQZGdwPRQrw+zZcZ5Eg@mail.gmail.com>
Subject: Re: log XLogPrefetch stats at end of recovery
To: Jakub Wartak <jakub.wartak@enterprisedb.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>,
	SATYANARAYANA NARLAPURAM <satyanarlapuram@gmail.com>,
 pgsql-hackers@postgresql.org
Content-Type: multipart/mixed; boundary="00000000000057c760064dc0efd5"
Archived-At: 
 <https://www.postgresql.org/message-id/CA%2B3i_M9s6T-jOsvSZk5y1HVvyz_RVbiEQZGdwPRQrw%2BzZcZ5Eg%40mail.gmail.com>
Precedence: bulk

--00000000000057c760064dc0efd5
Content-Type: multipart/alternative; boundary="00000000000057c75d064dc0efd3"

--00000000000057c75d064dc0efd3
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

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@enterpri=
sedb.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
> stats were not logged at the end of recovery. This log message will be
> useful to understand how effective XLogPrefetch was during recovery. Addi=
ng
> 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=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
> 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=E2=80=94however, I don't prefer doing a bunch of a=
tomic
> > 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 loggin=
g
> every now and then). If someone is interested in current state (or progre=
ss
> 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.

Regards,
Lakshmi

--00000000000057c75d064dc0efd3
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr"><div>Hi all,</div><div><br></div><div>Thank you for your f=
eedback. Please see the attached patch.</div><br><div class=3D"gmail_quote =
gmail_quote_container"><div dir=3D"ltr" class=3D"gmail_attr">On Mon, Mar 23=
, 2026 at 4:30=E2=80=AFAM Jakub Wartak &lt;<a href=3D"mailto:jakub.wartak@e=
nterprisedb.com">jakub.wartak@enterprisedb.com</a>&gt; wrote:<br></div><blo=
ckquote class=3D"gmail_quote" style=3D"margin:0px 0px 0px 0.8ex;border-left=
:1px solid rgb(204,204,204);padding-left:1ex">On Sun, Mar 22, 2026 at 1:43=
=E2=80=AFAM Bharath Rupireddy<br>
&lt;<a href=3D"mailto:bharath.rupireddyforpostgres@gmail.com" target=3D"_bl=
ank">bharath.rupireddyforpostgres@gmail.com</a>&gt; wrote:<br>
<br>
Hi,<br>
<br>
&gt; On Sat, Mar 21, 2026 at 1:16=E2=80=AFAM SATYANARAYANA NARLAPURAM<br>
&gt; &lt;<a href=3D"mailto:satyanarlapuram@gmail.com" target=3D"_blank">sat=
yanarlapuram@gmail.com</a>&gt; wrote:<br>
&gt; &gt;<br>
&gt; &gt; &gt; While investigating a long recovery, I noticed that XLogPref=
etch stats were not logged at the end of recovery. This log message will be=
 useful to understand how effective XLogPrefetch was during recovery. Addin=
g a patch to address this.<br>
&gt; &gt;<br>
&gt; &gt; Applied this patch and validated the log message. This log messag=
e appears to be useful to me, particularly while doing fleet wide analysis.=
<br>
&gt; &gt;<br>
&gt; &gt; 2026-03-20 23:33:13.756 PDT [2265441] LOG:=C2=A0 XLogPrefetcher s=
tats: prefetch=3D14, hit=3D6, skip_init=3D5, skip_new=3D28, skip_fpw=3D18, =
skip_rep=3D996<br>
&gt;<br>
&gt; This looks useful to understand how the prefetch helped during long re=
coveries.<br>
&gt;<br>
&gt; &gt; I am wondering if we can periodically log this in standby mode as=
 well, not just before promoting?<br>
&gt;<br>
&gt; Timer-based startup progress messaging allows logging such things<br>
&gt; (ereport_startup_progress API). There was an attempt to enable &quot;r=
edo<br>
&gt; in progress&quot; for standbys, but that seemed to flood the standby l=
ogs<br>
&gt; even at the default progress interval of 10 sec.<br>
&gt;<br>
&gt; Having said that, the prefetcher stats could be added to the existing<=
br>
&gt; ereport_startup_progress(&quot;redo in progress xxx&quot;) message tha=
t works<br>
&gt; for crash recoveries=E2=80=94however, I don&#39;t prefer doing a bunch=
 of atomic<br>
&gt; reads every progress interval of 10 sec.<br>
<br>
&gt; Therefore, logging at the end of recovery looks good to me.<br>
<br>
+1 from me too to only of logging at the end of recovery (so -1 to logging<=
br>
every now and then). If someone is interested in current state (or progress=
<br>
over time) I think he can query pg_stat_recovery_prefetch view already, eve=
n<br>
today, right?=C2=A0</blockquote><blockquote class=3D"gmail_quote" style=3D"=
margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-lef=
t:1ex">
&gt; I reviewed the patch. I have the following comment:<br>
&gt;<br>
&gt; + elog(LOG, &quot;XLogPrefetcher stats: prefetch=3D%lu, hit=3D%lu,<br>
&gt; skip_init=3D%lu, skip_new=3D%lu, skip_fpw=3D%lu, skip_rep=3D%lu&quot;,=
<br>
&gt;<br>
&gt; XLogPrefetcher is an internal data structure name, how about &quot;red=
o<br>
&gt; prefetch stats: xxxx&quot; to be consistent with other redo log messag=
es?<br>
<br>
+1<br></blockquote><div><br></div><div>please find the attached patch addre=
ssing this.=C2=A0</div><div><br></div><div>Regards,</div><div>Lakshmi</div>=
</div></div>

--00000000000057c75d064dc0efd3--

--00000000000057c760064dc0efd5
Content-Type: application/octet-stream;
	name="0001-log-prefetch-stats-at-end-of-recovery.patch"
Content-Disposition: attachment;
	filename="0001-log-prefetch-stats-at-end-of-recovery.patch"
Content-Transfer-Encoding: base64
Content-ID: <f_mn4cpwyv0>
X-Attachment-Id: f_mn4cpwyv0

RnJvbSBhZGM0MDE5MWZiMzliZWEzYWU0ZDAyZDU1NzNmNTAxNDQ4NDRlOTRkIE1vbiBTZXAgMTcg
MDA6MDA6MDAgMjAwMQpGcm9tOiBMYWtzaG1pIE4gPGxha3NobWluLmpoc0BnbWFpbC5jb20+CkRh
dGU6IFR1ZSwgMjQgTWFyIDIwMjYgMDE6MjM6MjQgLTA3MDAKU3ViamVjdDogW1BBVENIXSB4bG9n
cHJlZmV0Y2hlcjogbG9nIHByZWZldGNoIHN0YXRpc3RpY3MgYXQgZW5kIG9mIHJlY292ZXJ5CgpB
ZGQgWExvZ1ByZWZldGNoTG9nU3RhdHMoKSwgd2hpY2ggZW1pdHMgYSBMT0cgbWVzc2FnZSBzdW1t
YXJpc2luZyB0aGUKcHJlZmV0Y2ggY291bnRlcnMgKHByZWZldGNoLCBoaXQsIHNraXBfaW5pdCwg
c2tpcF9uZXcsIHNraXBfZnB3LApza2lwX3JlcCkgYWNjdW11bGF0ZWQgZHVyaW5nIHJlY292ZXJ5
LiBUaGUgZnVuY3Rpb24gaXMgY2FsbGVkIGZyb20KUGVyZm9ybVdhbFJlY292ZXJ5KCkgaW1tZWRp
YXRlbHkgYWZ0ZXIgdGhlICJyZWRvIGRvbmUiIG1lc3NhZ2UsIGdpdmluZwpvcGVyYXRvcnMgdmlz
aWJpbGl0eSBpbnRvIGhvdyBlZmZlY3RpdmUgV0FMIHByZWZldGNoaW5nIHdhcyBvdmVyIHRoZQpj
b3Vyc2Ugb2YgdGhlIHJlY292ZXJ5IHNlc3Npb24uCgpOby1vcCB3aGVuIHJlY292ZXJ5X3ByZWZl
dGNoID0gb2ZmLgotLS0KIHNyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2dwcmVmZXRjaGVy
LmMgfCAxOSArKysrKysrKysrKysrKysrKysrCiBzcmMvYmFja2VuZC9hY2Nlc3MvdHJhbnNhbS94
bG9ncmVjb3ZlcnkuYyAgIHwgIDIgKysKIHNyYy9pbmNsdWRlL2FjY2Vzcy94bG9ncHJlZmV0Y2hl
ci5oICAgICAgICAgfCAgMiArKwogMyBmaWxlcyBjaGFuZ2VkLCAyMyBpbnNlcnRpb25zKCspCgpk
aWZmIC0tZ2l0IGEvc3JjL2JhY2tlbmQvYWNjZXNzL3RyYW5zYW0veGxvZ3ByZWZldGNoZXIuYyBi
L3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2dwcmVmZXRjaGVyLmMKaW5kZXggYzIzNWVj
YTdjNTEuLjQ5YWNiMzZhZjFjIDEwMDY0NAotLS0gYS9zcmMvYmFja2VuZC9hY2Nlc3MvdHJhbnNh
bS94bG9ncHJlZmV0Y2hlci5jCisrKyBiL3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2dw
cmVmZXRjaGVyLmMKQEAgLTMzNSw2ICszMzUsMjUgQEAgWExvZ1ByZWZldGNoU2htZW1Jbml0KHZv
aWQpCiAJfQogfQogCisvKgorICogTG9nIGEgc3VtbWFyeSBvZiB0aGUgWExvZ1ByZWZldGNoZXIg
c3RhdHMuIEludGVuZGVkIHRvIGJlIGNhbGxlZCAKKyAqIGF0IHRoZSBlbmQgb2YgcmVjb3Zlcnkg
b3Igd2hlbiBhIHN0YW5kYnkgaXMgcHJvbW90ZWQuCisgKi8KK3ZvaWQKK1hMb2dQcmVmZXRjaExv
Z1N0YXRzKHZvaWQpCit7CisJaWYgKHJlY292ZXJ5X3ByZWZldGNoID09IFJFQ09WRVJZX1BSRUZF
VENIX09GRikKKwkJcmV0dXJuOworCisJZWxvZyhMT0csICJyZWRvIHByZWZldGNoIHN0YXRzOiBw
cmVmZXRjaD0lbHUsIGhpdD0lbHUsIHNraXBfaW5pdD0lbHUsIHNraXBfbmV3PSVsdSwgc2tpcF9m
cHc9JWx1LCBza2lwX3JlcD0lbHUiLAorCQkgcGdfYXRvbWljX3JlYWRfdTY0KCZTaGFyZWRTdGF0
cy0+cHJlZmV0Y2gpLAorCQkgcGdfYXRvbWljX3JlYWRfdTY0KCZTaGFyZWRTdGF0cy0+aGl0KSwK
KwkJIHBnX2F0b21pY19yZWFkX3U2NCgmU2hhcmVkU3RhdHMtPnNraXBfaW5pdCksCisJCSBwZ19h
dG9taWNfcmVhZF91NjQoJlNoYXJlZFN0YXRzLT5za2lwX25ldyksCisJCSBwZ19hdG9taWNfcmVh
ZF91NjQoJlNoYXJlZFN0YXRzLT5za2lwX2ZwdyksCisJCSBwZ19hdG9taWNfcmVhZF91NjQoJlNo
YXJlZFN0YXRzLT5za2lwX3JlcCkpOworfQorCiAvKgogICogQ2FsbGVkIHdoZW4gYW55IEdVQyBp
cyBjaGFuZ2VkIHRoYXQgYWZmZWN0cyBwcmVmZXRjaGluZy4KICAqLwpkaWZmIC0tZ2l0IGEvc3Jj
L2JhY2tlbmQvYWNjZXNzL3RyYW5zYW0veGxvZ3JlY292ZXJ5LmMgYi9zcmMvYmFja2VuZC9hY2Nl
c3MvdHJhbnNhbS94bG9ncmVjb3ZlcnkuYwppbmRleCA2ZDJjNGE4NmI5Ni4uNzQyY2I5MGRhOWIg
MTAwNjQ0Ci0tLSBhL3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2dyZWNvdmVyeS5jCisr
KyBiL3NyYy9iYWNrZW5kL2FjY2Vzcy90cmFuc2FtL3hsb2dyZWNvdmVyeS5jCkBAIC0xODQ1LDYg
KzE4NDUsOCBAQCBQZXJmb3JtV2FsUmVjb3Zlcnkodm9pZCkKIAkJCQllcnJtc2coInJlZG8gZG9u
ZSBhdCAlWC8lMDhYIHN5c3RlbSB1c2FnZTogJXMiLAogCQkJCQkgICBMU05fRk9STUFUX0FSR1Mo
eGxvZ3JlYWRlci0+UmVhZFJlY1B0ciksCiAJCQkJCSAgIHBnX3J1c2FnZV9zaG93KCZydTApKSk7
CisJCQorCQlYTG9nUHJlZmV0Y2hMb2dTdGF0cygpOwogCQl4dGltZSA9IEdldExhdGVzdFhUaW1l
KCk7CiAJCWlmICh4dGltZSkKIAkJCWVyZXBvcnQoTE9HLApkaWZmIC0tZ2l0IGEvc3JjL2luY2x1
ZGUvYWNjZXNzL3hsb2dwcmVmZXRjaGVyLmggYi9zcmMvaW5jbHVkZS9hY2Nlc3MveGxvZ3ByZWZl
dGNoZXIuaAppbmRleCA3ZWM0MGM0Yjc4Yi4uYTg2MjkyNGM4OTUgMTAwNjQ0Ci0tLSBhL3NyYy9p
bmNsdWRlL2FjY2Vzcy94bG9ncHJlZmV0Y2hlci5oCisrKyBiL3NyYy9pbmNsdWRlL2FjY2Vzcy94
bG9ncHJlZmV0Y2hlci5oCkBAIC0zNyw2ICszNyw3IEBAIGV4dGVybiB2b2lkIFhMb2dQcmVmZXRj
aFJlY29uZmlndXJlKHZvaWQpOwogZXh0ZXJuIHNpemVfdCBYTG9nUHJlZmV0Y2hTaG1lbVNpemUo
dm9pZCk7CiBleHRlcm4gdm9pZCBYTG9nUHJlZmV0Y2hTaG1lbUluaXQodm9pZCk7CiAKK2V4dGVy
biB2b2lkIFhMb2dQcmVmZXRjaExvZ1N0YXRzKHZvaWQpOwogZXh0ZXJuIHZvaWQgWExvZ1ByZWZl
dGNoUmVzZXRTdGF0cyh2b2lkKTsKIAogZXh0ZXJuIFhMb2dQcmVmZXRjaGVyICpYTG9nUHJlZmV0
Y2hlckFsbG9jYXRlKFhMb2dSZWFkZXJTdGF0ZSAqcmVhZGVyKTsKQEAgLTUyLDQgKzUzLDUgQEAg
ZXh0ZXJuIFhMb2dSZWNvcmQgKlhMb2dQcmVmZXRjaGVyUmVhZFJlY29yZChYTG9nUHJlZmV0Y2hl
ciAqcHJlZmV0Y2hlciwKIAogZXh0ZXJuIHZvaWQgWExvZ1ByZWZldGNoZXJDb21wdXRlU3RhdHMo
WExvZ1ByZWZldGNoZXIgKnByZWZldGNoZXIpOwogCisKICNlbmRpZgotLSAKMi40My4wCgo=
--00000000000057c760064dc0efd5--