Hi, hackers!
Now I complete extension that provides facility to see the current state
of query execution working on external session in form of EXPLAIN
ANALYZE output. This extension works on 9.5 version, for 9.6 and later
it doesn't support detailed statistics for parallel nodes yet.
I want to present patches to the latest version of PostgreSQL core to
enable this extension.
1. Patch that provides facility to send user signal to external backend
(custom_signals.patch).
This patch transparently extends process signal interface to enable
sending user defined signals (I call them - custom signals) and defining
callbacks to them. Formally it will appear in following manner:
/* Register custom signal and define signal callback */
Reason = RegisterCustomProcSignalHandler(sighandler);
void
sighandler(void)
{
...
}
/* On other session we can send process signal to the first backend */
SendProcSignal(pid, Reason, backendId)
The InterruptPending flag is set under process signal handling and
sighandler is called in CHECK_FOR_INTERRUPTS.
I use this patch to notice other backend to send its state to caller.
2. Patch that enables to interrupt the query executor
(executor_hooks.patch).
This patch enables to hang up hooks on executor function of each node
(ExecProcNode). I define hooks before any node execution and after
execution.
I use this patch to add possibility of query tracing by emitted rows
from any node. I interrupt query executor after any node delivers one or
zero rows to upper node. And after execution of specific number trace
steps I can get the query state of traceable backend which will be
somewhat deterministic. I use this possibility for regression tests of
my extension.
3. Patch that enables to output runtime explain statistics
(runtime_explain.patch).
This patch extends the regular explain functionality. The problem is in
the point that regular explain call makes result output after query
execution performing InstrEndLoop on nodes where necessary. My patch
introduces specific flag *runtime* that indicates whether we explain
running query and does some insertions in source code dedicated to
output the statistics of running query.
I want to notice that this patch is completed only for 9.5 postgres
version. For later versions there is not implemented detailed statistics
for parellel nodes. Now, I'm working at this feature.
That's all. CC welcome!
--
Maksim Milyutin
Postgres Professional: http://www.postgrespro.com
Russian Postgres Company
diff --git a/src/backend/storage/ipc/procsignal.c b/src/backend/storage/ipc/procsignal.c
index a3d6ac5..07270a9 100644
--- a/src/backend/storage/ipc/procsignal.c
+++ b/src/backend/storage/ipc/procsignal.c
@@ -59,12 +59,17 @@ typedef struct
*/
#define NumProcSignalSlots (MaxBackends + NUM_AUXPROCTYPES)
+static bool CustomSignalPendings[NUM_CUSTOM_PROCSIGNALS];
+static ProcSignalHandler_type CustomHandlers[NUM_CUSTOM_PROCSIGNALS];
+
static ProcSignalSlot *ProcSignalSlots = NULL;
static volatile ProcSignalSlot *MyProcSignalSlot = NULL;
static bool CheckProcSignal(ProcSignalReason reason);
static void CleanupProcSignalState(int status, Datum arg);
+static void CustomSignalInterrupt(ProcSignalReason reason);
+
/*
* ProcSignalShmemSize
* Compute space needed for procsignal's shared memory
@@ -165,6 +170,57 @@ CleanupProcSignalState(int status, Datum arg)
}
/*
+ * RegisterCustomProcSignalHandler
+ * Assign specific handler of custom process signal with new ProcSignalReason key.
+ * Return INVALID_PROCSIGNAL if all custom signals have been assigned.
+ */
+ProcSignalReason
+RegisterCustomProcSignalHandler(ProcSignalHandler_type handler)
+{
+ ProcSignalReason reason;
+
+ /* iterate through custom signal keys to find free spot */
+ for (reason = PROCSIG_CUSTOM_1; reason <= PROCSIG_CUSTOM_N; reason++)
+ if (!CustomHandlers[reason - PROCSIG_CUSTOM_1])
+ {
+ CustomHandlers[reason - PROCSIG_CUSTOM_1] = handler;
+ return reason;
+ }
+ return INVALID_PROCSIGNAL;
+}
+
+/*
+ * AssignCustomProcSignalHandler
+ * Assign handler of custom process signal with specific ProcSignalReason key.
+ * Return old ProcSignal handler.
+ * Assume incoming reason is one of custom ProcSignals.
+ */
+ProcSignalHandler_type
+AssignCustomProcSignalHandler(ProcSignalReason reason, ProcSignalHandler_type handler)
+{
+ ProcSignalHandler_type old;
+
+ Assert(reason >= PROCSIG_CUSTOM_1 && reason <= PROCSIG_CUSTOM_N);
+
+ old = CustomHandlers[reason - PROCSIG_CUSTOM_1];
+ CustomHandlers[reason - PROCSIG_CUSTOM_1] = handler;
+ return old;
+}
+
+/*
+ * GetCustomProcSignalHandler
+ * Get handler of custom process signal.
+ * Assume incoming reason is one of custom ProcSignals.
+ */
+ProcSignalHandler_type
+GetCustomProcSignalHandler(ProcSignalReason reason)
+{
+ Assert(reason >= PROCSIG_CUSTOM_1 && reason <= PROCSIG_CUSTOM_N);
+
+ return CustomHandlers[reason - PROCSIG_CUSTOM_1];
+}
+
+/*
* SendProcSignal
* Send a signal to a Postgres process
*
@@ -259,7 +315,8 @@ CheckProcSignal(ProcSignalReason reason)
void
procsignal_sigusr1_handler(SIGNAL_ARGS)
{
- int save_errno = errno;
+ int save_errno = errno;
+ ProcSignalReason reason;
if (CheckProcSignal(PROCSIG_CATCHUP_INTERRUPT))
HandleCatchupInterrupt();
@@ -288,9 +345,55 @@ procsignal_sigusr1_handler(SIGNAL_ARGS)
if (CheckProcSignal(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN))
RecoveryConflictInterrupt(PROCSIG_RECOVERY_CONFLICT_BUFFERPIN);
+ for (reason = PROCSIG_CUSTOM_1; reason <= PROCSIG_CUSTOM_N; reason++)
+ if (CheckProcSignal(reason))
+ CustomSignalInterrupt(reason);
+
SetLatch(MyLatch);
latch_sigusr1_handler();
errno = save_errno;
}
+
+/*
+ * Handle receipt of an interrupt indicating a custom process signal.
+ */
+static void
+CustomSignalInterrupt(ProcSignalReason reason)
+{
+ int save_errno = errno;
+
+ Assert(reason >= PROCSIG_CUSTOM_1 && reason <= PROCSIG_CUSTOM_N);
+
+ /* set interrupt flags */
+ InterruptPending = true;
+ CustomSignalPendings[reason - PROCSIG_CUSTOM_1] = true;
+
+ /* make sure the event is processed in due course */
+ SetLatch(MyLatch);
+
+ errno = save_errno;
+}
+
+/*
+ * CheckAndHandleCustomSignals
+ * Check custom signal flags and call handler assigned to that signal if it is not NULL.
+ * This function is called within CHECK_FOR_INTERRUPTS if interrupt have been occurred.
+ */
+void
+CheckAndHandleCustomSignals(void)
+{
+ int i;
+
+ for (i = 0; i < NUM_CUSTOM_PROCSIGNALS; i++)
+ if (CustomSignalPendings[i])
+ {
+ ProcSignalHandler_type handler;
+
+ CustomSignalPendings[i] = false;
+ handler = CustomHandlers[i];
+ if (handler)
+ handler();
+ }
+}
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 98ccbbb..c5d649c 100644
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -3005,6 +3005,8 @@ ProcessInterrupts(void)
if (ParallelMessagePending)
HandleParallelMessages();
+
+ CheckAndHandleCustomSignals();
}
diff --git a/src/include/storage/procsignal.h b/src/include/storage/procsignal.h
index f67b982..e941dcb 100644
--- a/src/include/storage/procsignal.h
+++ b/src/include/storage/procsignal.h
@@ -17,6 +17,8 @@
#include "storage/backendid.h"
+#define NUM_CUSTOM_PROCSIGNALS 64
+
/*
* Reasons for signalling a Postgres child process (a backend or an auxiliary
* process, like checkpointer). We can cope with concurrent signals for different
@@ -29,6 +31,8 @@
*/
typedef enum
{
+ INVALID_PROCSIGNAL = -1, /* Must be first */
+
PROCSIG_CATCHUP_INTERRUPT, /* sinval catchup interrupt */
PROCSIG_NOTIFY_INTERRUPT, /* listen/notify interrupt */
PROCSIG_PARALLEL_MESSAGE, /* message from cooperating parallel backend */
@@ -41,9 +45,20 @@ typedef enum
PROCSIG_RECOVERY_CONFLICT_BUFFERPIN,
PROCSIG_RECOVERY_CONFLICT_STARTUP_DEADLOCK,
+ PROCSIG_CUSTOM_1,
+ /*
+ * PROCSIG_CUSTOM_2,
+ * ...,
+ * PROCSIG_CUSTOM_N-1,
+ */
+ PROCSIG_CUSTOM_N = PROCSIG_CUSTOM_1 + NUM_CUSTOM_PROCSIGNALS - 1,
+
NUM_PROCSIGNALS /* Must be last! */
} ProcSignalReason;
+/* Handler of custom process signal */
+typedef void (*ProcSignalHandler_type) (void);
+
/*
* prototypes for functions in procsignal.c
*/
@@ -51,9 +66,15 @@ extern Size ProcSignalShmemSize(void);
extern void ProcSignalShmemInit(void);
extern void ProcSignalInit(int pss_idx);
+extern ProcSignalReason RegisterCustomProcSignalHandler(ProcSignalHandler_type handler);
+extern ProcSignalHandler_type AssignCustomProcSignalHandler(ProcSignalReason reason,
+ ProcSignalHandler_type handler);
+extern ProcSignalHandler_type GetCustomProcSignalHandler(ProcSignalReason reason);
extern int SendProcSignal(pid_t pid, ProcSignalReason reason,
BackendId backendId);
+extern void CheckAndHandleCustomSignals(void);
+
extern void procsignal_sigusr1_handler(SIGNAL_ARGS);
#endif /* PROCSIGNAL_H */
diff --git a/src/backend/executor/execProcnode.c b/src/backend/executor/execProcnode.c
index 554244f..7533cb2 100644
--- a/src/backend/executor/execProcnode.c
+++ b/src/backend/executor/execProcnode.c
@@ -117,7 +117,6 @@
#include "nodes/nodeFuncs.h"
#include "miscadmin.h"
-
/* ------------------------------------------------------------------------
* ExecInitNode
*
@@ -363,6 +362,9 @@ ExecInitNode(Plan *node, EState *estate, int eflags)
return result;
}
+/* Hooks for plugins to pre/post process ExecProcNode */
+PreExecProcNode_hook_type preExecProcNode_hook = NULL;
+PostExecProcNode_hook_type postExecProcNode_hook = NULL;
/* ----------------------------------------------------------------
* ExecProcNode
@@ -380,6 +382,9 @@ ExecProcNode(PlanState *node)
if (node->chgParam != NULL) /* something changed */
ExecReScan(node); /* let ReScan handle this */
+ if (preExecProcNode_hook)
+ preExecProcNode_hook(node);
+
if (node->instrument)
InstrStartNode(node->instrument);
@@ -540,6 +545,9 @@ ExecProcNode(PlanState *node)
if (node->instrument)
InstrStopNode(node->instrument, TupIsNull(result) ? 0.0 : 1.0);
+ if (postExecProcNode_hook)
+ postExecProcNode_hook(node, result);
+
return result;
}
diff --git a/src/include/executor/executor.h b/src/include/executor/executor.h
index 39521ed..9acbff7 100644
--- a/src/include/executor/executor.h
+++ b/src/include/executor/executor.h
@@ -95,6 +95,12 @@ extern PGDLLIMPORT ExecutorEnd_hook_type ExecutorEnd_hook;
typedef bool (*ExecutorCheckPerms_hook_type) (List *, bool);
extern PGDLLIMPORT ExecutorCheckPerms_hook_type ExecutorCheckPerms_hook;
+/* Hook for plugins to pre/post process ExecProcNode() */
+typedef void (*PreExecProcNode_hook_type) (PlanState *node);
+typedef void (*PostExecProcNode_hook_type) (PlanState *node, TupleTableSlot *result);
+extern PGDLLIMPORT PreExecProcNode_hook_type preExecProcNode_hook;
+extern PGDLLIMPORT PostExecProcNode_hook_type postExecProcNode_hook;
+
/*
* prototypes from functions in execAmi.c
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 82ba58e..bf7dfa6 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -667,15 +667,35 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
Instrumentation *instr = rInfo->ri_TrigInstrument + nt;
char *relname;
char *conname = NULL;
+ instr_time starttimespan;
+ double total;
+ double ntuples;
+ double ncalls;
- /* Must clean up instrumentation state */
- InstrEndLoop(instr);
+ if (!es->runtime)
+ {
+ /* Must clean up instrumentation state */
+ InstrEndLoop(instr);
+ }
+
+ /* Collect statistic variables */
+ if (!INSTR_TIME_IS_ZERO(instr->starttime))
+ {
+ INSTR_TIME_SET_CURRENT(starttimespan);
+ INSTR_TIME_SUBTRACT(starttimespan, instr->starttime);
+ }
+ else
+ INSTR_TIME_SET_ZERO(starttimespan);
+ total = instr->total + INSTR_TIME_GET_DOUBLE(instr->counter)
+ + INSTR_TIME_GET_DOUBLE(starttimespan);
+ ntuples = instr->ntuples + instr->tuplecount;
+ ncalls = ntuples + !INSTR_TIME_IS_ZERO(starttimespan);
/*
* We ignore triggers that were never invoked; they likely aren't
* relevant to the current query type.
*/
- if (instr->ntuples == 0)
+ if (ncalls == 0)
continue;
ExplainOpenGroup("Trigger", NULL, true, es);
@@ -701,9 +721,9 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
appendStringInfo(es->str, " on %s", relname);
if (es->timing)
appendStringInfo(es->str, ": time=%.3f calls=%.0f\n",
- 1000.0 * instr->total, instr->ntuples);
+ 1000.0 * total, ncalls);
else
- appendStringInfo(es->str, ": calls=%.0f\n", instr->ntuples);
+ appendStringInfo(es->str, ": calls=%.0f\n", ncalls);
}
else
{
@@ -712,8 +732,8 @@ report_triggers(ResultRelInfo *rInfo, bool show_relname, ExplainState *es)
ExplainPropertyText("Constraint Name", conname, es);
ExplainPropertyText("Relation", relname, es);
if (es->timing)
- ExplainPropertyFloat("Time", 1000.0 * instr->total, 3, es);
- ExplainPropertyFloat("Calls", instr->ntuples, 0, es);
+ ExplainPropertyFloat("Time", 1000.0 * total, 3, es);
+ ExplainPropertyFloat("Calls", ncalls, 0, es);
}
if (conname)
@@ -1225,8 +1245,11 @@ ExplainNode(PlanState *planstate, List *ancestors,
* instrumentation results the user didn't ask for. But we do the
* InstrEndLoop call anyway, if possible, to reduce the number of cases
* auto_explain has to contend with.
+ *
+ * if flag es->stateinfo is set i.e. when printing the current execution state
+ * this step of cleaning up is miss
*/
- if (planstate->instrument)
+ if (planstate->instrument && !es->runtime)
InstrEndLoop(planstate->instrument);
if (es->analyze &&
@@ -1259,7 +1282,7 @@ ExplainNode(PlanState *planstate, List *ancestors,
ExplainPropertyFloat("Actual Loops", nloops, 0, es);
}
}
- else if (es->analyze)
+ else if (es->analyze && !es->runtime)
{
if (es->format == EXPLAIN_FORMAT_TEXT)
appendStringInfoString(es->str, " (never executed)");
@@ -1275,6 +1298,75 @@ ExplainNode(PlanState *planstate, List *ancestors,
}
}
+ /*
+ * print the progress of node execution at current loop
+ */
+ if (planstate->instrument && es->analyze && es->runtime)
+ {
+ instr_time starttimespan;
+ double startup_sec;
+ double total_sec;
+ double rows;
+ double loop_num;
+ bool finished;
+
+ if (!INSTR_TIME_IS_ZERO(planstate->instrument->starttime))
+ {
+ INSTR_TIME_SET_CURRENT(starttimespan);
+ INSTR_TIME_SUBTRACT(starttimespan, planstate->instrument->starttime);
+ }
+ else
+ INSTR_TIME_SET_ZERO(starttimespan);
+ startup_sec = 1000.0 * planstate->instrument->firsttuple;
+ total_sec = 1000.0 * (INSTR_TIME_GET_DOUBLE(planstate->instrument->counter)
+ + INSTR_TIME_GET_DOUBLE(starttimespan));
+ rows = planstate->instrument->tuplecount;
+ loop_num = planstate->instrument->nloops + 1;
+
+ finished = planstate->instrument->nloops > 0
+ && !planstate->instrument->running
+ && INSTR_TIME_IS_ZERO(starttimespan);
+
+ if (!finished)
+ {
+ ExplainOpenGroup("Current loop", "Current loop", true, es);
+ if (es->format == EXPLAIN_FORMAT_TEXT)
+ {
+ if (es->timing)
+ {
+ if (planstate->instrument->running)
+ appendStringInfo(es->str,
+ " (Current loop: actual time=%.3f..%.3f rows=%.0f, loop number=%.0f)",
+ startup_sec, total_sec, rows, loop_num);
+ else
+ appendStringInfo(es->str,
+ " (Current loop: running time=%.3f actual rows=0, loop number=%.0f)",
+ total_sec, loop_num);
+ }
+ else
+ appendStringInfo(es->str,
+ " (Current loop: actual rows=%.0f, loop number=%.0f)",
+ rows, loop_num);
+ }
+ else
+ {
+ ExplainPropertyFloat("Actual Loop Number", loop_num, 0, es);
+ if (es->timing)
+ {
+ if (planstate->instrument->running)
+ {
+ ExplainPropertyFloat("Actual Startup Time", startup_sec, 3, es);
+ ExplainPropertyFloat("Actual Total Time", total_sec, 3, es);
+ }
+ else
+ ExplainPropertyFloat("Running Time", total_sec, 3, es);
+ }
+ ExplainPropertyFloat("Actual Rows", rows, 0, es);
+ }
+ ExplainCloseGroup("Current loop", "Current loop", true, es);
+ }
+ }
+
/* in text format, first line ends here */
if (es->format == EXPLAIN_FORMAT_TEXT)
appendStringInfoChar(es->str, '\n');
@@ -2269,20 +2361,17 @@ show_instrumentation_count(const char *qlabel, int which,
if (!es->analyze || !planstate->instrument)
return;
+ nloops = planstate->instrument->nloops;
if (which == 2)
- nfiltered = planstate->instrument->nfiltered2;
+ nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered2 / nloops : 0)
+ + planstate->instrument->nfiltered2;
else
- nfiltered = planstate->instrument->nfiltered1;
- nloops = planstate->instrument->nloops;
+ nfiltered = ((nloops > 0) ? planstate->instrument->accum_nfiltered1 / nloops : 0)
+ + planstate->instrument->nfiltered1;
/* In text mode, suppress zero counts; they're not interesting enough */
if (nfiltered > 0 || es->format != EXPLAIN_FORMAT_TEXT)
- {
- if (nloops > 0)
- ExplainPropertyFloat(qlabel, nfiltered / nloops, 0, es);
- else
- ExplainPropertyFloat(qlabel, 0.0, 0, es);
- }
+ ExplainPropertyFloat(qlabel, nfiltered, 0, es);
}
/*
@@ -2754,14 +2843,28 @@ show_modifytable_info(ModifyTableState *mtstate, List *ancestors,
double insert_path;
double other_path;
- InstrEndLoop(mtstate->mt_plans[0]->instrument);
+ if (!es->runtime)
+ InstrEndLoop(mtstate->mt_plans[0]->instrument);
/* count the number of source rows */
- total = mtstate->mt_plans[0]->instrument->ntuples;
- other_path = mtstate->ps.instrument->nfiltered2;
- insert_path = total - other_path;
+ other_path = mtstate->ps.instrument->accum_nfiltered2
+ + mtstate->ps.instrument->nfiltered2;
+
+ /*
+ * Insert occurs after extracting row from subplan and in runtime mode
+ * we can appear between these two operations - situation when
+ * total > insert_path + other_path. Therefore we don't know exactly
+ * whether last row from subplan is inserted.
+ * We don't print inserted tuples in runtime mode in order to not print
+ * inconsistent data
+ */
+ if (!es->runtime)
+ {
+ total = mtstate->mt_plans[0]->instrument->ntuples;
+ insert_path = total - other_path;
+ ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
+ }
- ExplainPropertyFloat("Tuples Inserted", insert_path, 0, es);
ExplainPropertyFloat("Conflicting Tuples", other_path, 0, es);
}
}
diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c
index 2614bf4..56d8a49 100644
--- a/src/backend/executor/instrument.c
+++ b/src/backend/executor/instrument.c
@@ -129,6 +129,8 @@ InstrEndLoop(Instrumentation *instr)
instr->total += totaltime;
instr->ntuples += instr->tuplecount;
instr->nloops += 1;
+ instr->accum_nfiltered1 += instr->nfiltered1;
+ instr->accum_nfiltered2 += instr->nfiltered2;
/* Reset for next cycle (if any) */
instr->running = false;
@@ -136,6 +138,8 @@ InstrEndLoop(Instrumentation *instr)
INSTR_TIME_SET_ZERO(instr->counter);
instr->firsttuple = 0;
instr->tuplecount = 0;
+ instr->nfiltered1 = 0;
+ instr->nfiltered2 = 0;
}
/* aggregate instrumentation information */
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d0a5ab..1f0bde7 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -35,6 +35,8 @@ typedef struct ExplainState
bool timing; /* print detailed node timing */
bool summary; /* print total planning and execution timing */
ExplainFormat format; /* output format */
+ bool runtime; /* print intermediate state of query execution,
+ not after completion */
/* state for output formatting --- not reset for each new plan tree */
int indent; /* current indentation level */
List *grouping_stack; /* format-specific grouping state */
diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h
index 8e5f0ec..2a1b512 100644
--- a/src/include/executor/instrument.h
+++ b/src/include/executor/instrument.h
@@ -52,14 +52,16 @@ typedef struct Instrumentation
instr_time counter; /* Accumulated runtime for this node */
double firsttuple; /* Time for first tuple of this cycle */
double tuplecount; /* Tuples emitted so far this cycle */
+ double nfiltered1; /* # tuples removed by scanqual or joinqual */
+ double nfiltered2; /* # tuples removed by "other" quals */
BufferUsage bufusage_start; /* Buffer usage at start */
/* Accumulated statistics across all completed cycles: */
double startup; /* Total startup time (in seconds) */
double total; /* Total total time (in seconds) */
double ntuples; /* Total tuples produced */
double nloops; /* # of run cycles for this node */
- double nfiltered1; /* # tuples removed by scanqual or joinqual */
- double nfiltered2; /* # tuples removed by "other" quals */
+ double accum_nfiltered1; /* # tuples removed by scanqual or joinqual on previous loops */
+ double accum_nfiltered2; /* # tuples removed by "other" quals on previous loops */
BufferUsage bufusage; /* Total buffer usage */
} Instrumentation;
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
