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

Hi,

First look at this patch, so I might be repeating stuff already commented on /
discussed.

On 2022-03-17 13:25:35 +0530, Bharath Rupireddy wrote:
> +--
> +-- pg_get_raw_wal_record()
> +--
> +CREATE FUNCTION pg_get_raw_wal_record(IN in_lsn pg_lsn,
> +    OUT start_lsn pg_lsn,
> +    OUT end_lsn pg_lsn,
> +    OUT prev_lsn pg_lsn,
> +    OUT record_length int4,
> +    OUT record bytea
> +)
> +AS 'MODULE_PATHNAME', 'pg_get_raw_wal_record'
> +LANGUAGE C CALLED ON NULL INPUT PARALLEL SAFE;

What is raw about the function?

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?


> +REVOKE EXECUTE ON FUNCTION pg_get_raw_wal_record(pg_lsn) FROM PUBLIC;
> +GRANT EXECUTE ON FUNCTION pg_get_raw_wal_record(pg_lsn) TO pg_read_server_files;
> +
> +--
> +-- pg_get_wal_record_info()
> +--
> +CREATE FUNCTION pg_get_wal_record_info(IN in_lsn pg_lsn,
> +    OUT start_lsn pg_lsn,
> +    OUT end_lsn pg_lsn,
> +    OUT prev_lsn pg_lsn,
> +    OUT xid xid,
> +    OUT resource_manager text,
> +    OUT record_length int4,
> +    OUT fpi_length int4,
> +	OUT description text,
> +    OUT block_ref text,
> +    OUT data_length int4,
> +    OUT data bytea
> +)
> +AS 'MODULE_PATHNAME', 'pg_get_wal_record_info'
> +LANGUAGE C CALLED ON NULL INPUT PARALLEL SAFE;
> +
> +REVOKE EXECUTE ON FUNCTION pg_get_wal_record_info(pg_lsn) FROM PUBLIC;
> +GRANT EXECUTE ON FUNCTION pg_get_wal_record_info(pg_lsn) TO pg_monitor;

I don't think it's appropriate for pg_monitor to see all the data in the WAL.

> +--
> +-- pg_get_wal_stats()
> +--
> +CREATE FUNCTION pg_get_wal_stats(IN start_lsn pg_lsn,
> +    IN end_lsn pg_lsn DEFAULT NULL,
> +    OUT resource_manager text,
> +    OUT count int8,
> +    OUT count_percentage float4,
> +    OUT record_length int8,
> +    OUT record_length_percentage float4,
> +    OUT fpi_length int8,
> +    OUT fpi_length_percentage float4
> +    )
> +RETURNS SETOF record AS $$
> +SELECT resource_manager,
> +    count(*) AS cnt,
> +    CASE WHEN count(*) > 0 THEN (count(*) * 100 / sum(count(*)) OVER total)::numeric(5,2) ELSE 0 END AS "count_%",
> +    sum(record_length) AS trecl,
> +    CASE WHEN sum(record_length) > 0 THEN (sum(record_length) * 100 / sum(sum(record_length)) OVER total)::numeric(5,2) ELSE 0 END AS "trecl_%",
> +    sum(fpi_length) AS tfpil,
> +    CASE WHEN sum(fpi_length) > 0 THEN (sum(fpi_length) * 100 / sum(sum(fpi_length)) OVER total)::numeric(5,2) ELSE 0 END AS "tfpil_%"
> +FROM pg_get_wal_records_info(start_lsn, end_lsn)
> +GROUP BY resource_manager
> +WINDOW total AS ();
> +$$ LANGUAGE SQL CALLED ON NULL INPUT PARALLEL SAFE;

This seems like an exceedingly expensive way to compute this. Not just because
of doing the grouping, window etc, but also because it's serializing the
"data" field from pg_get_wal_records_info() just to never use it. With any
appreciatable amount of data the return value pg_get_wal_records_info() will
be serialized into a on-disk tuplestore.

This is probably close to an order of magnitude slower than pg_waldump
--stats. Which imo renders this largely useless.

The column names don't seem great either. "tfpil"?


> +/*
> + * Module load callback.
> + */
> +void
> +_PG_init(void)
> +{
> +	/* Define custom GUCs and install hooks here, if any. */
> +
> +	/*
> +	 * Have EmitWarningsOnPlaceholders("pg_walinspect"); if custom GUCs are
> +	 * defined.
> +	 */
> +}
> +
> +/*
> + * Module unload callback.
> + */
> +void
> +_PG_fini(void)
> +{
> +	/* Uninstall hooks, if any. */
> +}

Why have this stuff if it's not used?


> +/*
> + * Validate given LSN and return the LSN up to which the server has WAL.
> + */
> +static XLogRecPtr
> +ValidateInputLSN(XLogRecPtr lsn)
> +{
> +	XLogRecPtr curr_lsn;
> +
> +	/* Validate input WAL LSN. */
> +	if (XLogRecPtrIsInvalid(lsn))
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("invalid WAL LSN")));
> +
> +	/*
> +	 * We determine the current LSN of the server similar to how page_read
> +	 * callback read_local_xlog_page does.
> +	 */
> +	if (!RecoveryInProgress())
> +		curr_lsn = GetFlushRecPtr(NULL);
> +	else
> +		curr_lsn = GetXLogReplayRecPtr(NULL);
> +
> +	Assert(!XLogRecPtrIsInvalid(curr_lsn));
> +
> +	if (lsn >= curr_lsn)
> +	{
> +		/*
> +	 	 * GetFlushRecPtr or GetXLogReplayRecPtr gives "end+1" LSN of the last
> +		 * record flushed or replayed respectively. But let's use the LSN up
> +		 * to "end" in user facing message.
> +	 	 */
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("cannot accept future input LSN"),
> +				 errdetail("Last known WAL LSN on the database system is %X/%X.",
> +						   LSN_FORMAT_ARGS(curr_lsn - 1))));
> +	}

> +	return curr_lsn;
> +}
> +
> +/*
> + * Validate given start LSN and end LSN, return the new end LSN in case user
> + * hasn't specified one.
> + */
> +static XLogRecPtr
> +ValidateStartAndEndLSNs(XLogRecPtr start_lsn, XLogRecPtr end_lsn)
> +{
> +	XLogRecPtr curr_lsn;
> +
> +	/* Validate WAL start LSN. */
> +	if (XLogRecPtrIsInvalid(start_lsn))
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("invalid WAL start LSN")));
> +
> +	if (!RecoveryInProgress())
> +		curr_lsn = GetFlushRecPtr(NULL);
> +	else
> +		curr_lsn = GetXLogReplayRecPtr(NULL);
> +
> +	if (start_lsn >= curr_lsn)
> +	{
> +		/*
> +	 	 * GetFlushRecPtr or GetXLogReplayRecPtr gives "end+1" LSN of the last
> +		 * record flushed or replayed respectively. But let's use the LSN up
> +		 * to "end" in user facing message.
> +	 	 */
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("cannot accept future start LSN"),
> +				 errdetail("Last known WAL LSN on the database system is %X/%X.",
> +						   LSN_FORMAT_ARGS(curr_lsn - 1))));
> +	}

> +	/*
> +	 * If end_lsn is specified, let's ensure that it's not a future LSN i.e.
> +	 * something the database system doesn't know about.
> +	 */
> +	if (!XLogRecPtrIsInvalid(end_lsn) &&
> +		(end_lsn >= curr_lsn))
> +	{
> +		/*
> +	 	 * GetFlushRecPtr or GetXLogReplayRecPtr gives "end+1" LSN of the last
> +		 * record flushed or replayed respectively. But let's use the LSN up
> +		 * to "end" in user facing message.
> +	 	 */
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("cannot accept future end LSN"),
> +				 errdetail("Last known WAL LSN on the database system is %X/%X.",
> +						   LSN_FORMAT_ARGS(curr_lsn - 1))));
> +	}
> +
> +	/*
> +	 * When end_lsn is not specified let's read up to the last WAL position
> +	 * known to be on the server.
> +	 */
> +	if (XLogRecPtrIsInvalid(end_lsn))
> +		end_lsn = curr_lsn;
> +
> +	Assert(!XLogRecPtrIsInvalid(end_lsn));
> +
> +	if (start_lsn >= end_lsn)
> +		ereport(ERROR,
> +				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
> +				 errmsg("WAL start LSN must be less than end LSN")));
> +
> +	return end_lsn;
> +}

These two functions are largely redundant, that doesn't seem great.


> +Datum
> +pg_get_raw_wal_record(PG_FUNCTION_ARGS)
> +{
> +#define PG_GET_RAW_WAL_RECORD_COLS 5
> +	XLogRecPtr	lsn;
> +	XLogRecord *record;
> +	XLogRecPtr	first_record;
> +	XLogReaderState *xlogreader;
> +	bytea	*raw_record;
> +	uint32	rec_len;
> +	char	*raw_record_data;
> +	TupleDesc	tupdesc;
> +	Datum	result;
> +	HeapTuple	tuple;
> +	Datum	values[PG_GET_RAW_WAL_RECORD_COLS];
> +	bool	nulls[PG_GET_RAW_WAL_RECORD_COLS];
> +	int	i = 0;
> +
> +	lsn = PG_GETARG_LSN(0);
> +
> +	(void) ValidateInputLSN(lsn);
> +
> +	/* Build a tuple descriptor for our result type. */
> +	if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE)
> +		elog(ERROR, "return type must be a row type");
> +
> +	xlogreader = InitXLogReaderState(lsn, &first_record);
> +
> +	Assert(xlogreader);
> +
> +	record = ReadNextXLogRecord(xlogreader, first_record);
> +
> +	rec_len = XLogRecGetTotalLen(xlogreader);
> +
> +	Assert(rec_len > 0);
> +

Most of this has another copy in pg_get_wal_record_info(). Can more of this be
deduplicated?


> +/*
> + * Get WAL record info.
> + */
> +static void
> +GetXLogRecordInfo(XLogReaderState *record, XLogRecPtr lsn,
> +				  Datum *values, bool *nulls, uint32 ncols)
> +{
> +	const char *id;
> +	const RmgrData *desc;
> +	uint32	fpi_len = 0;
> +	RelFileNode rnode;
> +	ForkNumber	forknum;
> +	BlockNumber blk;
> +	int	block_id;
> +	StringInfoData rec_desc;
> +	StringInfoData rec_blk_ref;
> +	StringInfoData temp;
> +	bytea	*data;
> +	char	*main_data;
> +	uint32	main_data_len;
> +	int	i = 0;
> +
> +	desc = &RmgrTable[XLogRecGetRmid(record)];
> +	initStringInfo(&rec_desc);
> +	id = desc->rm_identify(XLogRecGetInfo(record));
> +
> +	if (id == NULL)
> +		appendStringInfo(&rec_desc, "UNKNOWN (%x) ", XLogRecGetInfo(record) & ~XLR_INFO_MASK);
> +	else
> +		appendStringInfo(&rec_desc, "%s ", id);
> +
> +	initStringInfo(&temp);
> +	desc->rm_desc(&temp, record);
> +	appendStringInfo(&rec_desc, "%s", temp.data);
> +	pfree(temp.data);
> +	initStringInfo(&rec_blk_ref);

This seems unnecessarily wasteful. You serialize into one stringinfo, just to
then copy that stringinfo into another stringinfo. Just to then allocate yet
another stringinfo.


> +	/* Block references (detailed format). */

This comment seems copied from pg_waldump, but doesn't make sense here,
because there's no short format.


> +	for (block_id = 0; block_id <= record->max_block_id; block_id++)
> +	{
> +		if (!XLogRecHasBlockRef(record, block_id))
> +			continue;
> +
> +		XLogRecGetBlockTag(record, block_id, &rnode, &forknum, &blk);
> +
> +		if (forknum != MAIN_FORKNUM)
> +			appendStringInfo(&rec_blk_ref,
> +							"blkref #%u: rel %u/%u/%u fork %s blk %u",
> +							block_id, rnode.spcNode, rnode.dbNode,
> +							rnode.relNode, get_forkname(forknum), blk);
> +		else
> +			appendStringInfo(&rec_blk_ref,
> +							"blkref #%u: rel %u/%u/%u blk %u",
> +							block_id, rnode.spcNode, rnode.dbNode,
> +							rnode.relNode, blk);
> +
> +		if (XLogRecHasBlockImage(record, block_id))
> +		{
> +			uint8		bimg_info = record->blocks[block_id].bimg_info;
> +
> +			/* Calculate the amount of FPI data in the record. */
> +			fpi_len += record->blocks[block_id].bimg_len;
> +
> +			if (BKPIMAGE_COMPRESSED(bimg_info))
> +			{
> +				const char *method;
> +
> +				if ((bimg_info & BKPIMAGE_COMPRESS_PGLZ) != 0)
> +					method = "pglz";
> +				else if ((bimg_info & BKPIMAGE_COMPRESS_LZ4) != 0)
> +					method = "lz4";
> +				else
> +					method = "unknown";
> +
> +				appendStringInfo(&rec_blk_ref, " (FPW%s); hole: offset: %u, length: %u, "
> +								 "compression saved: %u, method: %s",
> +								 XLogRecBlockImageApply(record, block_id) ?
> +								 "" : " for WAL verification",
> +								 record->blocks[block_id].hole_offset,
> +								 record->blocks[block_id].hole_length,
> +								 BLCKSZ -
> +								 record->blocks[block_id].hole_length -
> +								 record->blocks[block_id].bimg_len,
> +								 method);
> +			}
> +			else
> +			{
> +				appendStringInfo(&rec_blk_ref, " (FPW%s); hole: offset: %u, length: %u",
> +								 XLogRecBlockImageApply(record, block_id) ?
> +								 "" : " for WAL verification",
> +								 record->blocks[block_id].hole_offset,
> +								 record->blocks[block_id].hole_length);
> +			}
> +		}
> +	}

To me duplicating this much code from waldump seems like a bad idea from a
maintainability POV.



> +/*
> + * Get info and data of all WAL records between start LSN and end LSN.
> + */
> +static void
> +GetWALRecordsInfoInternal(FunctionCallInfo fcinfo, XLogRecPtr start_lsn,
> +						  XLogRecPtr end_lsn)
> +{
> +#define PG_GET_WAL_RECORDS_INFO_COLS 11
> +	XLogRecPtr	first_record;
> +	XLogReaderState *xlogreader;
> +	ReturnSetInfo *rsinfo;
> +	TupleDesc	tupdesc;
> +	Tuplestorestate *tupstore;
> +	MemoryContext per_query_ctx;
> +	MemoryContext oldcontext;
> +	Datum	values[PG_GET_WAL_RECORDS_INFO_COLS];
> +	bool	nulls[PG_GET_WAL_RECORDS_INFO_COLS];
> +
> +	rsinfo = (ReturnSetInfo *) fcinfo->resultinfo;
> +
> +	/* Check to see if caller supports us returning a tuplestore. */
> +	if (rsinfo == NULL || !IsA(rsinfo, ReturnSetInfo))
> +		ereport(ERROR,
> +				(errcode(ERRCODE_FEATURE_NOT_SUPPORTED),
> +				 errmsg("set-valued function called in context that cannot accept a set")));
> +	if (!(rsinfo->allowedModes & SFRM_Materialize))
> +		ereport(ERROR,
> +				(errcode(ERRCODE_FEATURE_NOT_SUPPORTED),
> +				 errmsg("materialize mode required, but it is not allowed in this context")));
> +
> +	/* Build a tuple descriptor for our result type. */
> +	if (get_call_result_type(fcinfo, NULL, &tupdesc) != TYPEFUNC_COMPOSITE)
> +		elog(ERROR, "return type must be a row type");
> +
> +	/* Build tuplestore to hold the result rows. */
> +	per_query_ctx = rsinfo->econtext->ecxt_per_query_memory;
> +	oldcontext = MemoryContextSwitchTo(per_query_ctx);
> +	tupstore = tuplestore_begin_heap(true, false, work_mem);
> +	rsinfo->returnMode = SFRM_Materialize;
> +	rsinfo->setResult = tupstore;
> +	rsinfo->setDesc = tupdesc;

This should likely use the infrastructure introduced in 5b81703787bfc1e6072c8e37125eba0c5598b807.


> +	for (;;)
> +	{
> +		(void) ReadNextXLogRecord(xlogreader, first_record);
> +
> +		/*
> +		 * Let's not show the record info if it is spanning more than the
> +		 * end_lsn. EndRecPtr is "end+1" of the last read record, hence
> +		 * use "end" here.
> +		 */
> +		if ((xlogreader->EndRecPtr - 1) <= end_lsn)
> +		{
> +			GetXLogRecordInfo(xlogreader, xlogreader->currRecPtr, values, nulls,
> +						 	  PG_GET_WAL_RECORDS_INFO_COLS);
> +
> +			tuplestore_putvalues(tupstore, tupdesc, values, nulls);
> +		}
> +
> +		/* Exit loop if read up to end_lsn. */
> +		if (xlogreader->EndRecPtr >= end_lsn)
> +			break;

Seems weird to have both of these conditions separately.


Greetings,

Andres Freund