Subject: Re: pg_walinspect - a new extension to get raw WAL data and WAL stats

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 23 Mar 2022 11:51:25 +0900 (JST)

At Tue, 22 Mar 2022 11:00:06 -0700, Andres Freund <[email-masked]> wrote in 
> Hi,
> 
> On 2022-03-22 21:57:51 +0530, Bharath Rupireddy wrote:
> > > This is probably close to an order of magnitude slower than pg_waldump
> > > --stats. Which imo renders this largely useless.
> > 
> > Yeah that's true. Do you suggest having pg_get_wal_stats() a
> > c-function like in v8 patch [1]?
> 
> Yes.
>
> > SEe some numbers at [2] with pg_get_wal_stats using
> > pg_get_wal_records_info and pg_get_wal_records_info as a direct
> > c-function like in v8 patch [1]. A direct c-function always fares
> > better (84 msec vs 1400msec).
> 
> That indeed makes the view as is pretty much useless. And it'd probably be
> worse in a workload with longer records / many FPIs.

FWIW agreed. The SQL version is too slow..

> > > > +     for (block_id = 0; block_id <= record->max_block_id; block_id++)
> > > > +     {
> > >
> > > To me duplicating this much code from waldump seems like a bad idea from a
> > > maintainability POV.
> > 
> > Even if we were to put the above code from pg_walinspect and
> > pg_waldump into, say, walutils.c or some other existing file, there we
> > had to make if (pg_walinspect) appendStringInfo else if (pg_waldump)
> > printf() sort of thing, isn't it clumsy?
> 
> Why is that needed? Just use the stringinfo in both places? You're outputting
> the exact same thing in both places right now. There's already a stringinfo in
> XLogDumpDisplayRecord() these days (there wasn't back when pg_xlogddump was
> written), so you could just convert at least the relevant printfs in
> XLogDumpDisplayRecord().

> > Also, unnecessary if
> > conditions need to be executed for every record. For maintainability,
> > I added a note in pg_walinspect.c and pg_waldump.c to consider fixing
> > things in both places (of course this might sound dumbest way of doing
> > it, IMHO, it's sensible, given the if(pg_walinspect)-else
> > if(pg_waldump) sorts of code that we need to do in the common
> > functions). Thoughts?
> 
> IMO we shouldn't merge this with as much duplication as there is right now,
> the notes don't change that it's a PITA to maintain.

The two places emit different outputs but the only difference is the
delimiter between two blockrefs. (By the way, the current code forgets
to insert a delimiter there).  So even if the function took "bool
is_waldump", it is used only when appending a line delimiter.  It
would be nicer if the "bool is_waldump" were "char *delimiter".
Others might think differently, though..

So, the function looks like this.

StringInfo XLogBlockRefInfos(XLogReaderState *record, char *delimiter,
							uint32 &fpi_len);

> > Yeah. It is to handle some edge cases to print the WAL  upto end_lsn
> > and avoid waiting in read_local_xlog_page. I will change it.
> > 
> > Actually, there's an open point as specified in [3]. Any thoughts on it?
> 
> Seems more user-friendly to wait - it's otherwise hard for a user to know what
> LSN to put in.

I'm not sure it is user-friendly that the function "freeze"s for a
reason uncertain to the user..  Even if any results are accumulated
before waiting, all of them vanishes by entering Ctrl-C to release the
"freeze".

About the usefulness of the waiting behavior, it depends on what we
think the function's major use cases are.  Robert (AFAIU) thinks it as
a simple WAL dumper that is intended to use in some automated
mechanism.  The start/end LSNs simply identifies the records to emit.
No warning/errors and no waits except for apparently invalid inputs.

I thought it as a means by which to manually inspect wal on SQL
interface but don't have a strong opinion on the waiting behavior.
(Because I can avoid that by giving a valid LSN pair to the function
if I don't want it to "freeze".)

Anyway, the opinions here on the interface are described as follows.

A. as a diag interface for human use.

  1. If the whole region is filled with records, return them all.
  2. If start-LSN is too past, starts from the first available record.

  3-1. If start-LSN is in futnre, wait for the record to come.
  4-1. If end-LSN is in future, waits for new records.
  5-1. If end-LSN is too past, error out?

B. as a simple WAL dumper

  1. If the whole region is filled with records, return them all.
  2. If start-LSN is too past, starts from the first available record.

  3-2. If start-LSN is in futnre, returns nothig.
  4-2. If end-LSN is in future, ends with the last available record.
  5-2. If end-LSN is too past, returns northing.

1 and 2 are uncontroversial.

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Wed, 23 Mar 2022 11:57:46 +0900 (JST)

At Wed, 23 Mar 2022 11:51:25 +0900 (JST), Kyotaro Horiguchi <[email-masked]> wrote in 
> StringInfo XLogBlockRefInfos(XLogReaderState *record, char *delimiter,

By the way, [email-masked] has the subset of the
function.  So the function can be shared with the callers of
xlog_block_info but I'm not sure it is not too-much...

StringInfo XLogBlockRefInfos(XLogReaderState *record, char *delimiter,
		   					bool fpw_detail, uint32 &fpi_len);

regards.

---

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 23 Mar 2022 18:25:23 +0530

On Tue, Mar 22, 2022 at 11:30 PM Andres Freund <[email-masked]> wrote:
>
> > > Why "CALLED ON NULL INPUT"? It doesn't make sense to call the function with a
> > > NULL lsn, does it?  Also, that's the default, why is it restated here?
> >
> > pg_get_wal_records_info needed that option (if end_lsn being the
> > default, providing WAL info upto the end of WAL). Also, we can emit
> > better error message ("invalid WAL start LSN") instead of generic one.
> > I wanted to keep error message and code same across all the functions
> > hence CALLED ON NULL INPUT option for pg_get_raw_wal_record.
>
> I think it should be strict if it behaves strict. I fail to see what
> consistency in error messages is worth here. And I'd probably just create two
> different functions for begin and begin & end LSN and mark those as strict as
> well.

I'm okay with changing them to be STRICT. Right now, the behaviour of
pg_get_wal_records_info is this:
CREATE FUNCTION pg_get_wal_records_info(IN start_lsn pg_lsn,
    IN end_lsn pg_lsn DEFAULT NULL,

select pg_get_wal_records_info(start_lsn, end_lsn);
if start_lsn is future, then errors out
if end_lsn is future, then errors out
otherwise, returns WAL records info between start_lsn and end_lsn

select pg_get_wal_records_info(start_lsn);
if start_lsn is future, then errors out
sets end_lsn = current server lsn and returns WAL records info between
start_lsn and end_lsn

Same is true for pg_get_wal_stats.

Getting WAL records info provided start_lsn until end-of-WAL is a
basic ask and a good function to have. Now, if I were to make
pg_get_wal_records_info STRICT, then I would need to have another
function like pg_get_wal_records_info_till_end_of_wal/pg_get_wal_stats_till_end_of_wal
much like ones in few of my initial patches upthread.

Is it okay to have these functions pg_get_wal_records_info(start_lsn,
end_lsn)/pg_get_wal_stats(start_lsn, end_lsn) and
pg_get_wal_records_info_till_end_of_wal(start_lsn)/pg_get_wal_stats_till_end_of_wal(start_lsn)?
This way, it will be more clear to the user actually than to stuff
more than one behaviour in a single function with default values.

Please let me know your thoughts.

> Seems more user-friendly to wait - it's otherwise hard for a user to know what

I agree with Kyotaro-san that the wait behavior isn't a good choice,
because CTRL+C would not emit the accumulated info/stats unlike
pg_waldump. Also, with wait behaviour it's easy for a user to trick
the server with an unreasonably futuristic WAL LSN, say F/FFFFFFFF.
Also, if we use pg_walinspect functions, say, within a WAL monitoring
app, the wait behaviour isn't good there as it might look like the
functions hanging the app. We might think about adding a timeout for
waiting, but that doesn't seem an elegant way. Users/Apps can easily
figure out the LSNs to get WAL info/stats - either they can use
pg_current_wal_XXXX or by looking at the control file or server logs
or pg_stat_replication, what not. LSNs are everywhere within the
postgres eco-system.

Instead, the functions simply can figure out what's current server LSN
at-the-moment and choose to error out if any of the provided input LSN
is beyond that as it's being done currently. This looks simpler and
user-friendly.

>                                                         bool fpw_detail, uint32 &fpi_len);

Yes, putting them in a common function is a good idea. I'm thinking
something like below.
StringInfo
XLogBlockRefInfos(XLogReaderState *record, char *delimiter,
                  uint32 *fpi_len, bool detailed_format)

I will try to put the common functions in xlogreader.h/.c, so that
both pg_waldump and pg_walinspect can make use of it. Thoughts?

Regards,
Bharath Rupireddy.

---

From: Bharath Rupireddy <[email-masked]>
Date: Wed, 23 Mar 2022 21:36:09 +0530

> the notes don't change that it's a PITA to maintain.

Here's a refactoring patch that basically moves the pg_waldump's
functions and stats structures to xlogreader.h/.c so that the
pg_walinspect can reuse them. If it looks okay, I will send the
pg_walinspect patches based on it.

Regards,
Bharath Rupireddy.

---

From: Kyotaro Horiguchi <[email-masked]>
Date: Thu, 24 Mar 2022 13:52:46 +0900 (JST)

At Wed, 23 Mar 2022 21:36:09 +0530, Bharath Rupireddy <[email-masked]> wrote in 
> pg_walinspect patches based on it.

+void
+XLogRecGetBlockRefInfo(XLogReaderState *record, char *delimiter,
+					   uint32 *fpi_len, bool detailed_format,
+					   StringInfo buf)
...
+		if (detailed_format && delimiter)
+			appendStringInfoChar(buf, '\n');

It is odd that the variable "delimiter" is used as a bool in the
function, though it is a "char *", which I meant that it is used as
delimiter string (assuming that you might want to insert ", " between
two blkref descriptions).

+get_forkname(ForkNumber num)

forkNames[] is public and used in reinit.c.  I think we don't need
this function.

+#define MAX_XLINFO_TYPES 16
...
+	XLogRecStats	rmgr_stats[RM_NEXT_ID];
+	XLogRecStats	record_stats[RM_NEXT_ID][MAX_XLINFO_TYPES];
+} XLogStats;
+

This doesn't seem to be a part of xlogreader.  Couldn't we add a new
module "xlogstats"?  XLogRecGetBlockRefInfo also doesn't seem to me as
a part of xlogreader, the xlogstats looks like a better place.

+#define XLOG_GET_STATS_PERCENTAGE(n_pct, rec_len_pct, fpi_len_pct, \
+								  tot_len_pct, total_count, \

It doesn't need to be a macro. However in the first place I don't
think it is useful to have.  Rather it may be harmful since it doesn't
reduce complexity much but instead just hides details.  If we want to
avoid tedious repetitions of the same statements, a macro like the
following may work.

#define CALC_PCT (num, denom) ((denom) == 0 ? 0.0 ? 100.0 * (num) / (denom))
...
>   n_pct = CALC_PCT(n, total_count);
>   rec_len_pct = CALC_PCT(rec_len, total_rec_len);
>   fpi_len_pct = CALC_PCT(fpi_len, total_fpi_len);
>   tot_len_pct = CALC_PCT(tot_len, total_len);

But it is not seem that different if we directly write out the detail.

>   n_pct = (total_count == 0 ? 0 : 100.0 * n / total_count);
>   rec_len_pct = (total_rec_len == 0 ? 0 : 100.0 * rec_len / total_rec_len);
>   fpi_len_pct = (total_fpi_len == 0 ? 0 : 100.0 * fpi_len / total_fpi_len);
>   tot_len_pct = (total_len == 0 ? 0 : 100.0 * tot_len / total_len);

regards.

---

From: Bharath Rupireddy <[email-masked]>
Date: Thu, 24 Mar 2022 15:02:29 +0530

> two blkref descriptions).

I'm passing NULL if the delimiter isn't required (for pg_walinspect)
and I wanted to check if it's passed, so I was using the delimiter in
the condition. However, I now changed it to delimiter != NULL.

> forkNames[] is public and used in reinit.c.  I think we don't need

Yes. I removed it.

> a part of xlogreader, the xlogstats looks like a better place.

I'm not sure if it's worth adding new files xlogstats.h/.c just for 2
structures, 1 macro, and 2 functions with no plan to add new stats
structures or functions. Since xlogreader is the one that reads the
WAL, and is being included by both backend and other modules (tools
and extensions) IMO it's the right place. However, I can specify in
xlogreader that if at all the new stats related structures or
functions are going to be added, it's good to move them into a new
header and .c file.

Thoughts?

> >   tot_len_pct = (total_len == 0 ? 0 : 100.0 * tot_len / total_len);

I removed the XLOG_GET_STATS_PERCENTAGE macro.

Attaching v14 patch-set here with. It has bunch of other changes along
with the above:

1) Used STRICT for all the functions and introduced _till_end_of_wal
versions for pg_get_wal_records_info and pg_get_wal_stats.
2) Most of the code is reused between pg_walinspect and pg_waldump and
also within pg_walinspect.
3) Added read_local_xlog_page_no_wait without duplicating the code so
that the pg_walinspect functions don't wait even while finding the
first valid WAL record.
4) No function waits for future WAL lsn even to find the first valid WAL record.
5) Addressed the review comments raised upthread by Andres.

I hope this version makes the patch cleaner, please review it further.

Regards,
Bharath Rupireddy.

---

From: Andres Freund <[email-masked]>
Date: Thu, 24 Mar 2022 11:47:58 -0700

Hi,

> functions are going to be added, it's good to move them into a new

I don't like that location for XLogRecGetBlockRefInfo(). How about putting it
in xlogdesc.c - that kind of fits?

And what do you think about creating src/backend/access/rmgrdesc/stats.c for
XLogRecStoreStats()? It's not a perfect location, but not too bad either.

XLogRecGetLen() would be ok in xlogreader, but stats.c also would work?

Greetings,

Andres Freund

---

From: Bharath Rupireddy <[email-masked]>
Date: Fri, 25 Mar 2022 12:11:47 +0530

> in xlogdesc.c - that kind of fits?

Done.

> XLogRecGetLen() would be ok in xlogreader, but stats.c also would work?

I've added a new xlogstats.c/.h (as suggested by Kyotaro-san as well)
file under src/backend/access/transam/. I don't think the new file
fits well under rmgrdesc.

Attaching v15 patch-set, please have a look at it.

Regards,
Bharath Rupireddy.

---

From: RKN Sai Krishna <[email-masked]>
Date: Fri, 25 Mar 2022 20:37:31 +0530

Hi Bharath,

First look at the patch, bear with me if any of the following comments are
repeated.
1. With pg_get_wal_record(lsn), say a WAL record start, end lsn range
contains the specified LSN, wouldn't it be more meaningful to show the
corresponding WAL record.
For example, upon providing '0/17335E7' as input, and I see get the WAL
record ('0/1733618', '0/173409F') as output and not the one with start and
end lsn as ('0/17335E0', '0/1733617').

With pg_walfile_name(lsn), we can find the WAL segment file name that
contains the specified LSN.

2. I see the following output for pg_get_wal_record. Need to have a look at
the spaces I suppose.
rkn=# select * from pg_get_wal_record('0/4041728');
 start_lsn |  end_lsn  | prev_lsn  | record_length |

                 record

-----------+-----------+-----------+---------------+---------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-------------------------------------------------------------------------------------------------------------------------------------------------------------
 0/4041728 | 0/40421AF | 0/40416F0 |          2670 |
\x6e0a0000d2020000f016040400000000000a0000fef802b400007f7f00000000408fe738a25500000300000000000000010000007f06000000
4000003b0a00000000000012000000100101007f7f7f7f0885e738a25500003000c815380a03000885e738a255000000007f7f7f7f7f7f0000000078674301296000003000f8150020042000000000709e1203909
dba01c89c8601609cd00030986008f8956804d202000000000000000000000000120006001f00030820ffff5f04000000000001400000010000000000000004000000000080bf0200030000000000000000006100
0000610000000000000000000000000000000000000000000000000000000000000000000000330100000000000000bc02000001000000010000000000803f00000000000000b0060000010000000000000017000

3. Should these functions be running in standby mode too? We do not allow
WAL control functions to be executed during recovery right?

4. If the wal segment corresponding to the start lsn is removed, but there
are WAL records which could be read in the specified input lsn range, would
it be better to output the existing WAL records displaying a message that
it is a partial list of WAL records and the WAL files corresponding to the
rest are already removed, rather than erroring out saying "requested WAL
segment has already been removed"?

5. Following are very minor comments in the code

   - Correct the function description by removing "return the LSN up to
   which the server has WAL" for IsFutureLSN
   - In GetXLogRecordInfo, good to have pfree in place for rec_desc,
   rec_blk_ref, data
   - In GetXLogRecordInfo, can avoid calling XLogRecGetInfo(record)
   multiple times by capturing in a variable
   - In GetWALDetailsGuts, setting end_lsn could be done in single if else
   and similarly we can club the if statements verifying if the start lsn is a
   future lsn.

Thanks,
RKN

---

From: Bharath Rupireddy <[email-masked]>
Date: Sat, 26 Mar 2022 10:31:01 +0530

On Fri, Mar 25, 2022 at 8:37 PM RKN Sai Krishna
<[email-masked]> wrote:
>
> Hi Bharath,
>
> First look at the patch, bear with me if any of the following comments are repeated.

Thanks RKN, for playing around with the patches.

> 1. With pg_get_wal_record(lsn), say a WAL record start, end lsn range contains the specified LSN, wouldn't it be more meaningful to show the corresponding WAL record.

In general, all the functions will first look for a first valid WAL
record from the given input lsn/start lsn(XLogFindNextRecord) and then
give info of all the valid records including the first valid WAL
record until either the given end lsn or till end of WAL depending on
the function used.

> For example, upon providing '0/17335E7' as input, and I see get the WAL record ('0/1733618', '0/173409F') as output and not the one with start and end lsn as ('0/17335E0', '0/1733617').

If  '0/17335E7' is an LSN containing a valid WAL record,
pg_get_wal_record gives the info of that, otherwise if there's any
next valid WAL record, it finds and gives that info. '0/17335E0' is
before '0/17335E7' the input lsn, so it doesn't show that record, but
the next valid record.

All the pg_walinspect functions don't look for the nearest valid WAL
record (could be previous to input lsn or next to input lsn), but they
look for the next valid WAL record. This is because the xlogreader
infra now has no API for backward iteration from a given LSN ( it has
XLogFindNextRecord and XLogReadRecord which scans the WAL in forward
direction). But, it's a good idea to have XLogFindPreviousRecord and
XLogReadPreviousRecord versions (as we have links for previous WAL
record in each WAL record) but that's a separate discussion.

> With pg_walfile_name(lsn), we can find the WAL segment file name that contains the specified LSN.

Yes.

> 2. I see the following output for pg_get_wal_record. Need to have a look at the spaces I suppose.

I believe this is something psql does for larger column outputs for
pretty-display. When used in a non-psql client, the column values are
returned properly. Nothing to do with the pg_walinspect patches here.

> 3. Should these functions be running in standby mode too? We do not allow WAL control functions to be executed during recovery right?

There are functions that can be executable during recovery
pg_last_wal_receive_lsn, pg_last_wal_replay_lsn. The pg_walinspect
functions are useful even in recovery and I don't see a strong reason
to not support them. Hence, I'm right now supporting them.

> 4. If the wal segment corresponding to the start lsn is removed, but there are WAL records which could be read in the specified input lsn range, would it be better to output the existing WAL records displaying a message that it is a partial list of WAL records and the WAL files corresponding to the rest are already removed, rather than erroring out saying "requested WAL segment has already been removed"?

"requested WAL segment %s has already been removed" is a common error
across the xlogreader infra (see wal_segment_open) and I don't want to
invent a new behaviour. And all the segment_open callbacks report an
error when they are not finding the WAL file that they are looking
for.

> Correct the function description by removing "return the LSN up to which the server has WAL" for IsFutureLSN

That's fine, because it actually returns curr_lsn via the function
param curr_lsn. However, I modified the comment a bit.

> In GetXLogRecordInfo, good to have pfree in place for rec_desc, rec_blk_ref, data

No, we are just returning pointer to the string, not deep copying, see
CStringGetTextDatum. All the functions get executed within a
function's memory context and after handing off the results to the
client that gets deleted, deallocating all the memory.

> In GetXLogRecordInfo, can avoid calling XLogRecGetInfo(record) multiple times by capturing in a variable

XLogRecGetInfo is not a function, it's a macro, so that's fine.
#define XLogRecGetInfo(decoder) ((decoder)->record->header.xl_info)

> In GetWALDetailsGuts, setting end_lsn could be done in single if else and similarly we can club the if statements verifying if the start lsn is a future lsn.

The existing if conditions are:

    if (IsFutureLSN(start_lsn, &curr_lsn))
    if (!till_end_of_wal && end_lsn >= curr_lsn)
    if (till_end_of_wal)
    if (start_lsn >= end_lsn)

I clubbed them like this:
    if (!till_end_of_wal)
    if (IsFutureLSN(start_lsn, &curr_lsn))
    if (!till_end_of_wal && end_lsn >= curr_lsn)
    else if (till_end_of_wal)

Other if conditions are serving different purposes, so I'm leaving them as-is.

Attaching v16 patch-set, only change in v16-0002-pg_walinspect.patch,
others remain the same.

Regards,
Bharath Rupireddy.