From d82cea62d4ab53d3d77054286cddb1536172c8c0 Mon Sep 17 00:00:00 2001 From: benoit 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 | 17 +++++++++++++++++ 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, 119 insertions(+) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 0aec11f443..b687bf3507 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7696,6 +7696,24 @@ log_line_prefix = '%m [%p] %q%u@%d/%a ' + + log_parallel_workers (enum) + + log_parallel_workers configuration parameter + + + + + 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. + + + + log_parameter_max_length (integer) diff --git a/src/backend/access/brin/brin.c b/src/backend/access/brin/brin.c index 60853a0f6a..2a516911e7 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..6347a6b519 100644 --- a/src/backend/commands/vacuumparallel.c +++ b/src/backend/commands/vacuumparallel.c @@ -207,6 +207,9 @@ struct ParallelVacuumState int nindexes_parallel_cleanup; int nindexes_parallel_condcleanup; + int nworkers_planned; + int nworkers_launched; + /* Buffer access strategy used by leader process */ BufferAccessStrategy bstrategy; @@ -361,6 +364,9 @@ parallel_vacuum_init(Relation rel, Relation *indrels, int nindexes, if ((vacoptions & VACUUM_OPTION_PARALLEL_COND_CLEANUP) != 0) pvs->nindexes_parallel_condcleanup++; } + pvs->nworkers_planned = 0; + pvs->nworkers_launched = 0; + shm_toc_insert(pcxt->toc, PARALLEL_VACUUM_KEY_INDEX_STATS, indstats); pvs->indstats = indstats; @@ -435,6 +441,14 @@ parallel_vacuum_end(ParallelVacuumState *pvs, IndexBulkDeleteResult **istats) { Assert(!IsParallelWorker()); + if ((log_parallel_workers == LOG_PARALLEL_WORKERS_ALL && + pvs->nworkers_planned > 0) || + (log_parallel_workers == LOG_PARALLEL_WORKERS_FAILURE && + pvs->nworkers_planned > pvs->nworkers_launched)) + elog(LOG, "%i workers planned for index cleanup and bulkdelete (%i workers launched)", + pvs->nworkers_planned, + pvs->nworkers_launched); + /* Copy the updated statistics */ for (int i = 0; i < pvs->nindexes; i++) { @@ -737,6 +751,9 @@ parallel_vacuum_process_all_indexes(ParallelVacuumState *pvs, int num_index_scan for (int i = 0; i < pvs->pcxt->nworkers_launched; i++) InstrAccumParallelQuery(&pvs->buffer_usage[i], &pvs->wal_usage[i]); + + pvs->nworkers_planned += pvs->pcxt->nworkers_to_launch; + pvs->nworkers_launched += pvs->pcxt->nworkers_launched; } /* diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index 713cf3e802..fd18642692 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -492,6 +492,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 686309db58..1f9e2b1a33 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 88467977f8..b02d3c8f0c 100644 --- a/src/include/nodes/execnodes.h +++ b/src/include/nodes/execnodes.h @@ -727,6 +727,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