Subject: Add checkpoint and redo LSN to LogCheckpointEnd log message

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 23 Dec 2021 20:35:54 +0530

Hi,

It is useful (for debugging purposes) if the checkpoint end message
has the checkpoint LSN and REDO LSN [1]. It gives more context while
analyzing checkpoint-related issues. The pg_controldata gives the last
checkpoint LSN and REDO LSN, but having this info alongside the log
message helps analyze issues that happened previously, connect the
dots and identify the root cause.

Attaching a small patch herewith. Thoughts?

[1]
2021-12-23 14:58:54.694 UTC [1965649] LOG:  checkpoint starting:
shutdown immediate
2021-12-23 14:58:54.714 UTC [1965649] LOG:  checkpoint complete: wrote
0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.001 s, sync=0.001 s, total=0.025 s; sync files=0,
longest=0.000 s, average=0.000 s; distance=0 kB, estimate=0 kB;
LSN=0/14D0AD0, REDO LSN=0/14D0AD0

Regards,
Bharath Rupireddy.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Fri, 24 Dec 2021 14:51:34 +0900 (JST)

At Thu, 23 Dec 2021 20:35:54 +0530, Bharath Rupireddy <[email-masked]> wrote in 
> Attaching a small patch herewith. Thoughts?

A big +1 from me.  I thought about proposing the same in the past.

> LSN=0/14D0AD0, REDO LSN=0/14D0AD0

I thougt about something like the following, but your proposal may be
clearer.

> WAL range=[0/14D0340, 0/14D0AD0]

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 24 Dec 2021 17:37:51 +0530

> A big +1 from me.  I thought about proposing the same in the past.

Thanks for the review. I've added a CF entry to not lose track -
https://commitfest.postgresql.org/36/3474/.

> > WAL range=[0/14D0340, 0/14D0AD0]

Yeah the proposed in the v1 is clear saying checkpoint/restartpoint
LSN and REDO LSN.

Regards,
Bharath Rupireddy.

---

From: Michael Paquier <[email-masked]>
Date: Fri, 24 Dec 2021 21:11:59 +0900

> I thougt about something like the following, but your proposal may be

+    "LSN=%X/%X, REDO LSN=%X/%X",
This could be rather confusing for the average user, even if I agree
that this is some information that only an advanced user could
understand.  Could it be possible to define those fields in a more
deterministic way?  For one, it is hard to understand the relationship
between both fields without looking at the code, particulary if both
share the same value.  It is at least rather..  Well, mostly, easy to
guess what each other field means in this context, which is not the
case of what you are proposing here.  One idea could be use also
"start point" for REDO, for example. 
--
Michael

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 24 Dec 2021 17:54:02 +0530

> "start point" for REDO, for example.

How about "location=%X/%X, REDO start location=%X/%X"? The entire log
message can look like below:

2021-12-24 12:20:19.140 UTC [1977834] LOG:  checkpoint
complete:location=%X/%X, REDO start location=%X/%X; wrote 7 buffers
(0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s,
sync=0.007 s, total=0.192 s; sync files=5, longest=0.005 s,
average=0.002 s; distance=293 kB, estimate=56584 kB

Another variant:
2021-12-24 12:20:19.140 UTC [1977834] LOG:  checkpoint completed at
location=%X/%X with REDO start location=%X/%X: wrote 7 buffers (0.0%);
0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.007
s, total=0.192 s; sync files=5, longest=0.005 s, average=0.002 s;
distance=293 kB, estimate=56584 kB
2021-12-24 12:20:19.140 UTC [1977834] LOG:  restartpoint completed at
location=%X/%X with REDO start location=%X/%X: wrote 7 buffers (0.0%);
0 WAL file(s) added, 0 removed, 0 recycled; write=0.005 s, sync=0.007
s, total=0.192 s; sync files=5, longest=0.005 s, average=0.002 s;
distance=293 kB, estimate=56584 kB

Thoughts?

Regards,
Bharath Rupireddy.

---

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 28 Dec 2021 08:26:28 +0530

> distance=293 kB, estimate=56584 kB

Here are the 2 patches.

one(v2-1-XXX.patch) adding the info as:
2021-12-28 02:44:34.870 UTC [2384386] LOG:  checkpoint complete:
location=0/1B03040, REDO start location=0/1B03008; wrote 466 buffers
(2.8%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.014 s,
sync=0.038 s, total=0.072 s; sync files=21, longest=0.022 s,
average=0.002 s; distance=6346 kB, estimate=6346 kB

another(v2-2-XXX.patch) adding the info as:
2021-12-28 02:52:24.464 UTC [2394396] LOG:  checkpoint completed at
location=0/212FFC8 with REDO start location=0/212FF90: wrote 451
buffers (2.8%); 0 WAL file(s) added, 0 removed, 1 recycled;
write=0.012 s, sync=0.032 s, total=0.071 s; sync files=6,
longest=0.022 s, average=0.006 s; distance=6272 kB, estimate=6272 kB

attaching v1-0001-XXX from the initial mail again just for the sake of
completion:

Thoughts?

Regards,
Bharath Rupireddy.