Date: Sun, 25 Oct 2020 09:42:46 -0700
From: Noah Misch <noah@leadboat.com>
To: Tom Lane <tgl@sss.pgh.pa.us>
Cc: Peter Geoghegan <pg@bowt.ie>, Andres Freund <andres@anarazel.de>,
	Phil Florent <philflorent@hotmail.com>,
	PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: pgstat_report_activity() and parallel CREATE INDEX (was:
 Parallel index creation & pg_stat_activity)
Message-ID: <20201025164246.GD2651494@rfd.leadboat.com>
References: 
 <CAH2-WzkryAPcQOHBJKuDKfni-HGFny31yjcbM-yp5HO-71iCdw@mail.gmail.com>
 <CAH2-Wzmf-34hD4n40uTuE-ZY9P5c+mvhFbCdQfN=KrKiVm3j3A@mail.gmail.com>
 <20201014022636.GA1962668@rfd.leadboat.com>
 <CAH2-Wzm2K3jqurvFfCXsV=s+NvPf9V=6YDDcVPk-0kORL9D7oA@mail.gmail.com>
 <20201025051836.GC2651494@rfd.leadboat.com>
 <439665.1603637570@sss.pgh.pa.us>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="R+My9LyyhiUvIEro"
Content-Disposition: inline
In-Reply-To: <439665.1603637570@sss.pgh.pa.us>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk


--R+My9LyyhiUvIEro
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Sun, Oct 25, 2020 at 10:52:50AM -0400, Tom Lane wrote:
> Noah Misch <noah@leadboat.com> writes:
> > On Sat, Oct 17, 2020 at 08:39:35AM -0700, Peter Geoghegan wrote:
> >> I also prefer 2.
> 
> > Thanks.  Here is the pair of patches I plan to use.  The second is equivalent
> > to v0; I just added a log message.
> 
> The change in worker_spi_main seems a little weird/lazy.  I'd
> be inclined to set and clear debug_query_string each time through
> the loop, so that those operations are adjacent to the other
> status-reporting operations, as they are in initialize_worker_spi.

True.  Emitting STATEMENT message fields during ProcessConfigFile(PGC_SIGHUP)
would be wrong.

> I don't really like modifying a StringInfo while debug_query_string
> is pointing at it, either.  Yeah, you'll *probably* get away with
> that because the buffer is unlikely to move, but since the whole
> exercise can only benefit crash-debugging scenarios, it'd be better
> to be more paranoid.

Good point.  This is supposed to be example code, so it shouldn't cut corners.

> One idea is to set debug_query_string immediately before each SPI_execute
> and clear it just afterwards, rather than trying to associate it with
> pgstat_report_activity calls.

Each elog(FATAL) check deserves a STATEMENT field if it fires, so I think that
would be too early to clear.  Here's an version fixing the defects.  In
worker_spi_main(), the timing now mirrors postgres.c.  initialize_worker_spi()
is doing something not directly possible from SQL, so I improvised there.

--R+My9LyyhiUvIEro
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment;
 filename="worker_spi-debug_query_string-v2.patch"

Author:     Noah Misch <noah@leadboat.com>
Commit:     Noah Misch <noah@leadboat.com>

    Set debug_query_string in worker_spi.
    
    This makes elog.c emit the string, which is good practice for a
    background worker that executes SQL strings.
    
    Reviewed by Tom Lane.
    
    Discussion: https://postgr.es/m/20201014022636.GA1962668@rfd.leadboat.com

diff --git a/src/test/modules/worker_spi/worker_spi.c b/src/test/modules/worker_spi/worker_spi.c
index 1c7b17c..258237f 100644
--- a/src/test/modules/worker_spi/worker_spi.c
+++ b/src/test/modules/worker_spi/worker_spi.c
@@ -114,53 +114,59 @@ initialize_worker_spi(worktable *table)
 	PushActiveSnapshot(GetTransactionSnapshot());
 	pgstat_report_activity(STATE_RUNNING, "initializing worker_spi schema");
 
 	/* XXX could we use CREATE SCHEMA IF NOT EXISTS? */
 	initStringInfo(&buf);
 	appendStringInfo(&buf, "select count(*) from pg_namespace where nspname = '%s'",
 					 table->schema);
 
+	debug_query_string = buf.data;
 	ret = SPI_execute(buf.data, true, 0);
 	if (ret != SPI_OK_SELECT)
 		elog(FATAL, "SPI_execute failed: error code %d", ret);
 
 	if (SPI_processed != 1)
 		elog(FATAL, "not a singleton result");
 
 	ntup = DatumGetInt64(SPI_getbinval(SPI_tuptable->vals[0],
 									   SPI_tuptable->tupdesc,
 									   1, &isnull));
 	if (isnull)
 		elog(FATAL, "null result");
 
 	if (ntup == 0)
 	{
+		debug_query_string = NULL;
 		resetStringInfo(&buf);
 		appendStringInfo(&buf,
 						 "CREATE SCHEMA \"%s\" "
 						 "CREATE TABLE \"%s\" ("
 						 "		type text CHECK (type IN ('total', 'delta')), "
 						 "		value	integer)"
 						 "CREATE UNIQUE INDEX \"%s_unique_total\" ON \"%s\" (type) "
 						 "WHERE type = 'total'",
 						 table->schema, table->name, table->name, table->name);
 
 		/* set statement start time */
 		SetCurrentStatementStartTimestamp();
 
+		debug_query_string = buf.data;
 		ret = SPI_execute(buf.data, false, 0);
 
 		if (ret != SPI_OK_UTILITY)
 			elog(FATAL, "failed to create my schema");
+
+		debug_query_string = NULL;	/* rest is not statement-specific */
 	}
 
 	SPI_finish();
 	PopActiveSnapshot();
 	CommitTransactionCommand();
+	debug_query_string = NULL;
 	pgstat_report_activity(STATE_IDLE, NULL);
 }
 
 void
 worker_spi_main(Datum main_arg)
 {
 	int			index = DatumGetInt32(main_arg);
 	worktable  *table;
@@ -257,16 +263,17 @@ worker_spi_main(Datum main_arg)
 		 *
 		 * The pgstat_report_activity() call makes our activity visible
 		 * through the pgstat views.
 		 */
 		SetCurrentStatementStartTimestamp();
 		StartTransactionCommand();
 		SPI_connect();
 		PushActiveSnapshot(GetTransactionSnapshot());
+		debug_query_string = buf.data;
 		pgstat_report_activity(STATE_RUNNING, buf.data);
 
 		/* We can now execute queries via SPI */
 		ret = SPI_execute(buf.data, false, 0);
 
 		if (ret != SPI_OK_UPDATE_RETURNING)
 			elog(FATAL, "cannot select from table %s.%s: error code %d",
 				 table->schema, table->name, ret);
@@ -286,16 +293,17 @@ worker_spi_main(Datum main_arg)
 		}
 
 		/*
 		 * And finish our transaction.
 		 */
 		SPI_finish();
 		PopActiveSnapshot();
 		CommitTransactionCommand();
+		debug_query_string = NULL;
 		pgstat_report_stat(false);
 		pgstat_report_activity(STATE_IDLE, NULL);
 	}
 
 	proc_exit(1);
 }
 
 /*

--R+My9LyyhiUvIEro--