Hi,
Here is a new version of the patch. Sorry for the long delay, I was hit
by a motivation drought and was quite busy otherwise.
The guc is now called `log_parallel_workers` and has three possible values:
* "none": disables logging
* "all": logs parallel worker info for all parallel queries or utilities
* "failure": logs only when the number of parallel workers planned
couldn't be reached.
For this, I added several members to the EState struct.
Each gather node / gather merge node updates the values and the
offending queries are displayed during standard_ExecutorEnd.
For CREATE INDEX / REINDEX on btree and brin, I check the parallel
context struct (pcxt) during _bt_end_parallel() or _brin_end_parallel()
and display a log message when needed.
For vacuum, I do the same in parallel_vacuum_end().
I added some information to the error message for parallel queries as an
experiment. I find it useful, but it can be removed, if you re not
convinced.
2024-08-27 15:59:11.089 CEST [54585] LOG: 1 parallel nodes planned (1
obtained all their workers, 0 obtained none), 2 workers planned (2
workers launched)
2024-08-27 15:59:11.089 CEST [54585] STATEMENT: EXPLAIN (ANALYZE)
SELECT i, avg(j) FROM test_pql GROUP BY i;
2024-08-27 15:59:14.006 CEST [54585] LOG: 2 parallel nodes planned (0
obtained all their workers, 1 obtained none), 4 workers planned (1
workers launched)
2024-08-27 15:59:14.006 CEST [54585] STATEMENT: EXPLAIN (ANALYZE)
SELECT i, avg(j) FROM test_pql GROUP BY i
UNION
SELECT i, avg(j) FROM test_pql GROUP BY i;
For CREATE INDEX / REDINDEX / VACUUMS:
2024-08-27 15:58:59.769 CEST [54521] LOG: 1 workers planned (0 workers
launched)
2024-08-27 15:58:59.769 CEST [54521] STATEMENT: REINDEX TABLE test_pql;
Do you think this is better?
I am not sure if a struct is needed to store the es_nworkers* and if the
modification I did to parallel.h is ok.
Thanks to: Jehan-Guillaume de Rorthais, Guillaume Lelarge and Franck
Boudehen for the help and motivation boost.
(sorry for the spam, I had to resend the mail to the list)
--
Benoit Lobréau
Consultant
http://dalibo.com
From 940e1d1149f777733ea00e7a0a688da67f492f6d Mon Sep 17 00:00:00 2001
From: benoit <benoit.lobr...@dalibo.com>
Date: Mon, 26 Aug 2024 13:48:44 +0200
Subject: [PATCH] Add logging for parallel worker usage
The new guc log_parallel_workers controls whether a log message is
produced to display information on the number of workers spawned when a
parallel query or utility is executed. The default value is `none`
which disables logging. `all` displays information for all parallel
queries, whereas `failures` displays information only when the number of
workers launched is lower than the number of planned workers. This new
parameter can help database administrators and developers diagnose
performance issues related to parallelism and optimize the configuration
of the system accordingly.
---
doc/src/sgml/config.sgml | 18 ++++++++++++++++++
src/backend/access/brin/brin.c | 8 ++++++++
src/backend/access/nbtree/nbtsort.c | 8 ++++++++
src/backend/commands/vacuumparallel.c | 8 ++++++++
src/backend/executor/execMain.c | 12 ++++++++++++
src/backend/executor/execUtils.c | 6 ++++++
src/backend/executor/nodeGather.c | 8 ++++++++
src/backend/executor/nodeGatherMerge.c | 8 ++++++++
src/backend/utils/misc/guc_tables.c | 12 ++++++++++++
src/backend/utils/misc/postgresql.conf.sample | 1 +
src/include/access/parallel.h | 15 +++++++++++++++
src/include/nodes/execnodes.h | 6 ++++++
12 files changed, 110 insertions(+)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 2937384b00..234552c3fc 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -7700,6 +7700,24 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-parallel-workers" xreflabel="log_parallel_workers">
+ <term><varname>log_parallel_workers</varname> (<type>enum</type>)
+ <indexterm>
+ <primary><varname>log_parallel_workers</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Controls whether a log message is produced to display information on the number of
+ workers spawned when a parallel query or utility is executed. The default value is
+ <literal>none</literal> which disables logging. <literal>all</literal> displays
+ information for all parallel queries, whereas <literal>failures</literal> displays
+ information only when the number of workers launched is lower than the number of
+ planned workers.
+ </para>
+ </listitem>
+ </varlistentry>
+
<varlistentry id="guc-log-parameter-max-length" xreflabel="log_parameter_max_length">
<term><varname>log_parameter_max_length</varname> (<type>integer</type>)
<indexterm>
diff --git a/src/backend/access/brin/brin.c b/src/backend/access/brin/brin.c
index 6467bed604..0d53d5c575 100644
--- a/src/backend/access/brin/brin.c
+++ b/src/backend/access/brin/brin.c
@@ -2540,6 +2540,14 @@ _brin_end_parallel(BrinLeader *brinleader, BrinBuildState *state)
/* Shutdown worker processes */
WaitForParallelWorkersToFinish(brinleader->pcxt);
+ if ((log_parallel_workers == LOG_PARALLEL_WORKERS_ALL &&
+ brinleader->pcxt->nworkers_to_launch > 0) ||
+ (log_parallel_workers == LOG_PARALLEL_WORKERS_FAILURE &&
+ brinleader->pcxt->nworkers_to_launch > brinleader->pcxt->nworkers_launched))
+ elog(LOG, "%i workers planned (%i workers launched)",
+ brinleader->pcxt->nworkers_to_launch,
+ brinleader->pcxt->nworkers_launched);
+
/*
* Next, accumulate WAL usage. (This must wait for the workers to finish,
* or we might get incomplete data.)
diff --git a/src/backend/access/nbtree/nbtsort.c b/src/backend/access/nbtree/nbtsort.c
index f5d7b3b0c3..eaa3e1bac1 100644
--- a/src/backend/access/nbtree/nbtsort.c
+++ b/src/backend/access/nbtree/nbtsort.c
@@ -1611,6 +1611,14 @@ _bt_end_parallel(BTLeader *btleader)
/* Shutdown worker processes */
WaitForParallelWorkersToFinish(btleader->pcxt);
+ if ((log_parallel_workers == LOG_PARALLEL_WORKERS_ALL &&
+ btleader->pcxt->nworkers_to_launch > 0) ||
+ (log_parallel_workers == LOG_PARALLEL_WORKERS_FAILURE &&
+ btleader->pcxt->nworkers_to_launch > btleader->pcxt->nworkers_launched))
+ elog(LOG, "%i workers planned (%i workers launched)",
+ btleader->pcxt->nworkers_to_launch,
+ btleader->pcxt->nworkers_launched);
+
/*
* Next, accumulate WAL usage. (This must wait for the workers to finish,
* or we might get incomplete data.)
diff --git a/src/backend/commands/vacuumparallel.c b/src/backend/commands/vacuumparallel.c
index 22c057fe61..fc40b68903 100644
--- a/src/backend/commands/vacuumparallel.c
+++ b/src/backend/commands/vacuumparallel.c
@@ -435,6 +435,14 @@ parallel_vacuum_end(ParallelVacuumState *pvs, IndexBulkDeleteResult **istats)
{
Assert(!IsParallelWorker());
+ if ((log_parallel_workers == LOG_PARALLEL_WORKERS_ALL &&
+ pvs->pcxt->nworkers_to_launch > 0) ||
+ (log_parallel_workers == LOG_PARALLEL_WORKERS_FAILURE &&
+ pvs->pcxt->nworkers_to_launch > pvs->pcxt->nworkers_launched))
+ elog(LOG, "%i workers planned (%i workers launched)",
+ pvs->pcxt->nworkers_to_launch,
+ pvs->pcxt->nworkers_launched);
+
/* Copy the updated statistics */
for (int i = 0; i < pvs->nindexes; i++)
{
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 29e186fa73..42c4f9fc54 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -480,6 +480,18 @@ standard_ExecutorEnd(QueryDesc *queryDesc)
Assert(estate != NULL);
+ if ((log_parallel_workers == LOG_PARALLEL_WORKERS_ALL &&
+ estate->es_workers_planned > 0) ||
+ (log_parallel_workers == LOG_PARALLEL_WORKERS_FAILURE &&
+ estate->es_workers_planned != estate->es_workers_launched))
+ elog(LOG, "%i parallel nodes planned (%i obtained all their workers, %i obtained none), "
+ "%i workers planned (%i workers launched)",
+ estate->es_parallelized_nodes,
+ estate->es_parallelized_nodes_success,
+ estate->es_parallelized_nodes_no_workers,
+ estate->es_workers_planned,
+ estate->es_workers_launched);
+
/*
* Check that ExecutorFinish was called, unless in EXPLAIN-only mode. This
* Assert is needed because ExecutorFinish is new as of 9.1, and callers
diff --git a/src/backend/executor/execUtils.c b/src/backend/executor/execUtils.c
index 5737f9f4eb..9d1cef6d28 100644
--- a/src/backend/executor/execUtils.c
+++ b/src/backend/executor/execUtils.c
@@ -162,6 +162,12 @@ CreateExecutorState(void)
estate->es_jit_flags = 0;
estate->es_jit = NULL;
+ estate->es_parallelized_nodes = 0;
+ estate->es_parallelized_nodes_success = 0;
+ estate->es_parallelized_nodes_no_workers = 0;
+ estate->es_workers_launched = 0;
+ estate->es_workers_planned = 0;
+
/*
* Return the executor state structure
*/
diff --git a/src/backend/executor/nodeGather.c b/src/backend/executor/nodeGather.c
index 5d4ffe989c..8a8994c19a 100644
--- a/src/backend/executor/nodeGather.c
+++ b/src/backend/executor/nodeGather.c
@@ -181,6 +181,13 @@ ExecGather(PlanState *pstate)
LaunchParallelWorkers(pcxt);
/* We save # workers launched for the benefit of EXPLAIN */
node->nworkers_launched = pcxt->nworkers_launched;
+ /* We save the total # of workers launched for logging purposes */
+ estate->es_workers_launched += pcxt->nworkers_launched;
+ estate->es_workers_planned += pcxt->nworkers_to_launch;
+ estate->es_parallelized_nodes += 1;
+
+ if (pcxt->nworkers_to_launch == pcxt->nworkers_launched)
+ estate->es_parallelized_nodes_success += 1;
/* Set up tuple queue readers to read the results. */
if (pcxt->nworkers_launched > 0)
@@ -198,6 +205,7 @@ ExecGather(PlanState *pstate)
/* No workers? Then never mind. */
node->nreaders = 0;
node->reader = NULL;
+ estate->es_parallelized_nodes_no_workers += 1;
}
node->nextreader = 0;
}
diff --git a/src/backend/executor/nodeGatherMerge.c b/src/backend/executor/nodeGatherMerge.c
index 45f6017c29..83611bd503 100644
--- a/src/backend/executor/nodeGatherMerge.c
+++ b/src/backend/executor/nodeGatherMerge.c
@@ -222,6 +222,13 @@ ExecGatherMerge(PlanState *pstate)
LaunchParallelWorkers(pcxt);
/* We save # workers launched for the benefit of EXPLAIN */
node->nworkers_launched = pcxt->nworkers_launched;
+ /* We save the total # of workers launched for logging purposes */
+ estate->es_workers_launched += pcxt->nworkers_launched;
+ estate->es_workers_planned += pcxt->nworkers_to_launch;
+ estate->es_parallelized_nodes += 1;
+
+ if (pcxt->nworkers_to_launch == pcxt->nworkers_launched)
+ estate->es_parallelized_nodes_success += 1;
/* Set up tuple queue readers to read the results. */
if (pcxt->nworkers_launched > 0)
@@ -239,6 +246,7 @@ ExecGatherMerge(PlanState *pstate)
/* No workers? Then never mind. */
node->nreaders = 0;
node->reader = NULL;
+ estate->es_parallelized_nodes_no_workers += 1;
}
}
diff --git a/src/backend/utils/misc/guc_tables.c b/src/backend/utils/misc/guc_tables.c
index af227b1f24..891f71e980 100644
--- a/src/backend/utils/misc/guc_tables.c
+++ b/src/backend/utils/misc/guc_tables.c
@@ -482,6 +482,7 @@ extern const struct config_enum_entry archive_mode_options[];
extern const struct config_enum_entry recovery_target_action_options[];
extern const struct config_enum_entry wal_sync_method_options[];
extern const struct config_enum_entry dynamic_shared_memory_options[];
+extern const struct config_enum_entry log_parallel_workers_options[];
/*
* GUC option variables that are exported from this module
@@ -526,6 +527,7 @@ int log_min_duration_statement = -1;
int log_parameter_max_length = -1;
int log_parameter_max_length_on_error = 0;
int log_temp_files = -1;
+int log_parallel_workers = LOG_PARALLEL_WORKERS_NONE;
double log_statement_sample_rate = 1.0;
double log_xact_sample_rate = 0;
char *backtrace_functions;
@@ -5196,6 +5198,16 @@ struct config_enum ConfigureNamesEnum[] =
NULL, NULL, NULL
},
+ {
+ {"log_parallel_workers", PGC_SUSET, LOGGING_WHAT,
+ gettext_noop("Log information about parallel worker usage"),
+ NULL
+ },
+ &log_parallel_workers,
+ LOG_PARALLEL_WORKERS_NONE, log_parallel_workers_options,
+ NULL, NULL, NULL
+ },
+
/* End-of-list marker */
{
{NULL, 0, 0, NULL, NULL}, NULL, 0, NULL, NULL, NULL, NULL
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index 667e0dc40a..7cd9c0f3f8 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -619,6 +619,7 @@
#log_temp_files = -1 # log temporary files equal or larger
# than the specified size in kilobytes;
# -1 disables, 0 logs all temp files
+#log_parallel_workers = none # none, all, failure
#log_timezone = 'GMT'
# - Process Title -
diff --git a/src/include/access/parallel.h b/src/include/access/parallel.h
index 69ffe5498f..ed33e545d7 100644
--- a/src/include/access/parallel.h
+++ b/src/include/access/parallel.h
@@ -19,6 +19,20 @@
#include "postmaster/bgworker.h"
#include "storage/shm_mq.h"
#include "storage/shm_toc.h"
+#include "utils/guc.h"
+
+typedef enum log_parallel_workers_option_list {
+ LOG_PARALLEL_WORKERS_NONE=0,
+ LOG_PARALLEL_WORKERS_ALL,
+ LOG_PARALLEL_WORKERS_FAILURE,
+} log_parallel_workers_option_list;
+
+static const struct config_enum_entry log_parallel_workers_options[] = {
+ {"none", LOG_PARALLEL_WORKERS_NONE, false},
+ {"all", LOG_PARALLEL_WORKERS_ALL, false},
+ {"failure", LOG_PARALLEL_WORKERS_FAILURE, false},
+ {NULL, 0, false}
+};
typedef void (*parallel_worker_main_type) (dsm_segment *seg, shm_toc *toc);
@@ -56,6 +70,7 @@ typedef struct ParallelWorkerContext
extern PGDLLIMPORT volatile sig_atomic_t ParallelMessagePending;
extern PGDLLIMPORT int ParallelWorkerNumber;
extern PGDLLIMPORT bool InitializingParallelWorker;
+extern PGDLLEXPORT int log_parallel_workers;
#define IsParallelWorker() (ParallelWorkerNumber >= 0)
diff --git a/src/include/nodes/execnodes.h b/src/include/nodes/execnodes.h
index af7d8fd1e7..06b48bfe41 100644
--- a/src/include/nodes/execnodes.h
+++ b/src/include/nodes/execnodes.h
@@ -724,6 +724,12 @@ typedef struct EState
*/
List *es_insert_pending_result_relations;
List *es_insert_pending_modifytables;
+
+ int es_parallelized_nodes;
+ int es_parallelized_nodes_success;
+ int es_parallelized_nodes_no_workers;
+ int es_workers_launched;
+ int es_workers_planned;
} EState;
--
2.45.2
