Subject: Re: Add checkpoint and redo LSN to LogCheckpointEnd log message

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 1 Feb 2022 00:23:10 +0530

On Tue, Feb 1, 2022 at 12:00 AM Nathan Bossart <[email-masked]> wrote:
>
> On Mon, Jan 31, 2022 at 11:45:19PM +0530, Bharath Rupireddy wrote:
> > Thanks. Here are 2 patches, 0001 for adding checkpoint lsn and redo
> > lsn in the checkpoint completed message and 0002 for changing the
> > "location" to LSN in pg_controdata's output. With the 0002,
> > pg_control_checkpont, pg_controldata and checkpoint completed message
> > will all be in sync with the checkpoint lsn and redo lsn.
>
> I think the pg_controldata change needs some extra spaces for alignment,
> but otherwise these patches seem reasonable to me.

Thanks. My bad it was. Changed in v6.

Regards,
Bharath Rupireddy.

---

From: Nathan Bossart <[email-masked]>
Date: Mon, 31 Jan 2022 17:44:35 -0800

> Thanks. My bad it was. Changed in v6.

LGTM

-- 
Nathan Bossart
Amazon Web Services: https://aws.amazon.com

---

From: Fujii Masao <[email-masked]>
Date: Tue, 1 Feb 2022 12:40:41 +0900

>> Thanks. My bad it was. Changed in v6.

-				(errmsg("restartpoint complete: wrote %d buffers (%.1f%%); "
+				(errmsg("restartpoint complete: lsn=%X/%X, redo lsn=%X/%X; "
+						"wrote %d buffers (%.1f%%); "
  						"%d WAL file(s) added, %d removed, %d recycled; "
  						"write=%ld.%03d s, sync=%ld.%03d s, total=%ld.%03d s; "
  						"sync files=%d, longest=%ld.%03d s, average=%ld.%03d s; "
  						"distance=%d kB, estimate=%d kB",
+						LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo),
+						LSN_FORMAT_ARGS(ControlFile->checkPoint),

The order of arguments for LSN seems wrong. LSN_FORMAT_ARGS(ControlFile->checkPoint) should be specified ahead of LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo)?

Could you tell me why the information for LSN is reported earlierly in the log message? Since ordinally users would be more interested in the information about I/O by checkpoint, the information for LSN should be placed later? Sorry if this was already discussed.

Regards,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION

---

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 1 Feb 2022 09:31:09 +0530

> The order of arguments for LSN seems wrong. LSN_FORMAT_ARGS(ControlFile->checkPoint) should be specified ahead of LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo)?

Thanks. Corrected.

> Could you tell me why the information for LSN is reported earlierly in the log message? Since ordinally users would be more interested in the information about I/O by checkpoint, the information fo…

It is useful (for debugging purposes) if the checkpoint end message
has the checkpoint LSN(end) and REDO LSN(start). 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.

Regards,
Bharath Rupireddy.

---

From: Fujii Masao <[email-masked]>
Date: Tue, 1 Feb 2022 13:19:43 +0900

>> The order of arguments for LSN seems wrong. LSN_FORMAT_ARGS(ControlFile->checkPoint) should be specified ahead of LSN_FORMAT_ARGS(ControlFile->checkPointCopy.redo)?

Thanks!

> the dots and identify the root cause.

My previous comment was confusing... Probably I understand why you tried to put this information in checkpoint log message. But I was suggesting to put that information at the end of log message instead of the beginning of it. Because ordinary users would be less interested in this LSN information than other ones like the number of buffers written.

Regards,

---

From: Bharath Rupireddy <[email-masked]>
Date: Tue, 1 Feb 2022 10:08:04 +0530

> My previous comment was confusing... Probably I understand why you tried to put this information in checkpoint log message. But I was suggesting to put that information at the end of log message in…

Actually, there's no strong reason to put LSN info at the beginning of
the message except that LSN/REDO LSN next to the
checkpoint/restartpoint complete would make the users understand the
LSN and REDO LSN belong to the checkpoint/restartpoint. Since this
wasn't a strong reason, I agree to keep it at the end.

Modified in v8.

[1]
2022-02-01 04:34:17.657 UTC [3597073] LOG:  checkpoint complete: wrote
21 buffers (0.1%); 0 WAL file(s) added, 0 removed, 0 recycled;
write=0.004 s, sync=0.008 s, total=0.031 s; sync files=18,
longest=0.006 s, average=0.001 s; distance=77 kB, estimate=77 kB;
lsn=0/14D5AF0, redo lsn=0/14D5AB8

Regards,
Bharath Rupireddy.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Tue, 01 Feb 2022 15:27:56 +0900 (JST)

At Tue, 1 Feb 2022 10:08:04 +0530, Bharath Rupireddy <[email-masked]> wrote in 
> lsn=0/14D5AF0, redo lsn=0/14D5AB8

0001 looks good to me.

I tend to agree to 0002.

FWIW, I collected other user-facing usage of "location" as LSN.

xlog.c:5965, 6128:
  (errmsg("recovery stopping before WAL location (LSN) \"%X/%X\"",

xlog.c:6718:
  (errmsg("control file contains invalid checkpoint location")));

xlog.c:6846:
  (errmsg("starting point-in-time recovery to WAL location (LSN) \"%X/%X\"",

xlog.c:6929:
  (errmsg("could not find redo location referenced by checkpoint record"),

xlog.c:11298, 11300:  (in backup-label)
  appendStringInfo(labelfile, "START WAL LOCATION: %X/%X (file %s)\n",
  appendStringInfo(labelfile, "CHECKPOINT LOCATION: %X/%X\n",
  (and corresponding reader-code)

xlog,c:11791, 11793:  (in backup history file)
  fprintf(fp, "START WAL LOCATION: %X/%X (file %s)\n",
  fprintf(fp, "STOP WAL LOCATION: %X/%X (file %s)\n",
  (and corresponding reader-code)

repl_scanner.l:151:
  yyerror("invalid streaming start location");

pg_proc.dat:
  many function descriptions use "location" as LSN.

pg_waldump.c:768,777,886,938,1029,1071,1083:
  printf(_("  -e, --end=RECPTR       stop reading at WAL location RECPTR\n"));
  printf(_("  -s, --start=RECPTR     start reading at WAL location RECPTR\n"));
  pg_log_error("could not parse end WAL location \"%s\"",
  pg_log_error("could not parse start WAL location \"%s\"",
  pg_log_error("start WAL location %X/%X is not inside file \"%s\"",
  pg_log_error("end WAL location %X/%X is not inside file \"%s\"",
  pg_log_error("no start WAL location given");

pg_basebackup.c:476, 615: (confusing with file/directory path..)
  pg_log_error("could not parse write-ahead log location \"%s\"",
  pg_log_error("could not parse write-ahead log location \"%s\"",

pg_rewind.c:346:
  pg_log_info("servers diverged at WAL location %X/%X on timeline %u",
pg_rewind/timeline.c:82:
  pg_log_error("Expected a write-ahead log switchpoint location.");

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center