[Bug]: Duplicating instrumentation in hypertable_modify_explain makes planstate tree troublesome for extensions

[GetsuDer]

What type of bug is this?

Unexpected error

What subsystems and features are affected?

Query executor, Query planner

What happened?

During ExplainPrintPlan, timescaledb modifies HypertableModifyState's child node, ModifyTableState, so they share an instrumenation structure, which includes parameters for tracking runtime of the node. Normally it is fine, since ExplainPrintPlan is called after the query was already executed.

	/*
	 * Since we hijack the ModifyTable node, instrumentation on ModifyTable will
	 * be missing so we set it to instrumentation of HypertableModify node.
	 */
	if (mtstate->ps.instrument)
	{
		/*
		 * INSERT .. ON CONFLICT statements record few metrics in the ModifyTable node.
		 * So, copy them into HypertableModify node before replacing them.
		 */
		node->ss.ps.instrument->ntuples2 = mtstate->ps.instrument->ntuples2;
		node->ss.ps.instrument->nfiltered1 = mtstate->ps.instrument->nfiltered1;
	}
	mtstate->ps.instrument = node->ss.ps.instrument;

But it is possible for extensions to call ExplainPrintPlan in hooks before the query was executed, for monitoring of some kind, for example. The looks and description of this function give no indication that it will somehow change the planstate tree it is used on.

In this case, an error "InstrStartNode called twice in a row" will be shown for queries, which

1. contain HypertableModfiy node
2. are run with explain (verbose true, analyze true, timing true)

The reason is the check in InstrStartNode that we don't run it twice on the same node.

/* Entry to a plan node */
void
InstrStartNode(Instrumentation *instr)
{
	if (instr->need_timer &&
		!INSTR_TIME_SET_CURRENT_LAZY(instr->starttime))
		elog(ERROR, "InstrStartNode called twice in a row");

	/* save buffer usage totals at node entry, if needed */
	if (instr->need_bufusage)
		instr->bufusage_start = pgBufferUsage;

	if (instr->need_walusage)
		instr->walusage_start = pgWalUsage;
}

Since HypertableModfiyState and ModifyTableState share instrumentation, the check fails.

This situation may lead to users trying timescaledb with other extensions and finding out unexpected incompatiblity.

Since I don't know much about how timescaledb works, I can't suggest better solution than turning timings off for HypertableModfiyState node in hypertable_modify_explain, right after instrumentation is shared between two nodes. (Setting need_timer to false). It is not a good solution, but it at least will allow users run their queries without unexpected errors.

TimescaleDB version affected

2.17.2

PostgreSQL version used

16.6

What operating system did you use?

Ubuntu 22.04

What installation method did you use?

Source

What platform did you run on?

On prem/Self-hosted

Relevant log output and stack trace

postgres=# CREATE EXTENSION example_extension;
CREATE EXTENSION
postgres=# CREATE EXTENSION timescaledb;
CREATE EXTENSION
postgres=# CREATE TABLE "public"."data"( 
"timestamp" timestamptz NOT NULL);
CREATE TABLE
postgres=# SELECT create_hypertable('data','timestamp');
 create_hypertable 
-------------------
 (1,public,data,t)
(1 row)

postgres=# explain (verbose true, analyze true, timing true) INSERT INTO data VALUES (now());
ERROR:  InstrStartNode called twice in a row

How can we reproduce the bug?

I wrote a simple extension, which does nothing more than call ExplainPrintPlan in StartExecutor hook. It can be found here: https://github.com/GetsuDer/example_extension

and build with use of PGXS. The main part is the following:


static void
example_ExecutorStart(QueryDesc *queryDesc, int eflags)
{
	ExplainState *es = NewExplainState();

	if (prev_ExecutorStart)
		prev_ExecutorStart(queryDesc, eflags);
	else
		standard_ExecutorStart(queryDesc, eflags);

	ExplainBeginOutput(es);
	ExplainPrintPlan(es, queryDesc);
	ExplainEndOutput(es);

	elog(LOG, "Query plan from ExecutorStart hook: %s", es->str->data);
}

This are the contents of the test script.
test.sql:

CREATE EXTENSION example_extension;
CREATE EXTENSION timescaledb;
CREATE TABLE "public"."data"(
"timestamp" timestamptz NOT NULL);
SELECT create_hypertable('data','timestamp');
explain (verbose true, analyze true, timing true) INSERT INTO data VALUES (now());

postgresql.conf need to contain the following line.

shared_preload_libraries='example_extension, timescaledb'

The result is the following error message:

ERROR:  InstrStartNode called twice in a row