Add GUC for setting background worker log level

To avoid having to spam the log with unecessary background worker
progress messages a GUC for controlling the background worker log level
is introduced. This can be set using `ALTER SYSTEM` plus a call of
`pg_reload_conf()` and will set the `log_min_messages` for the
background workers only (scheduler and all job runners).

It also adds some additional job progress messages at debug level.

Fixes #6161

.unreleased/fix_6188

@@ -0,0 +1,2 @@
+Fixes: #6188 Add GUC for setting background worker log level
+Thanks: @jflambert for reporting the issue

src/bgw/job.c

@@ -1197,6 +1197,10 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS)
 
 	BackgroundWorkerInitializeConnectionByOid(db_oid, params.user_oid, 0);
 
+	log_min_messages = ts_guc_bgw_log_level;
+
+	elog(DEBUG2, "job %d started execution", params.job_id);
+
 	ts_license_enable_module_loading();
 
 	INSTR_TIME_SET_CURRENT(start);
@@ -1216,6 +1220,8 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS)
 	if (job == NULL)
 		elog(ERROR, "job %d not found when running the background worker", params.job_id);
 
+	elog(DEBUG2, "job %d (%s) found", params.job_id, NameStr(job->fd.application_name));
+
 	pgstat_report_appname(NameStr(job->fd.application_name));
 	MemoryContext oldcontext = CurrentMemoryContext;
 	TimestampTz start_time = DT_NOBEGIN, finish_time = DT_NOBEGIN;
@@ -1324,7 +1330,7 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS)
 	INSTR_TIME_SET_CURRENT(duration);
 	INSTR_TIME_SUBTRACT(duration, start);
 
-	elog(LOG,
+	elog(DEBUG1,
 		 "job %d (%s) exiting with %s: execution time %.2f ms",
 		 params.job_id,
 		 NameStr(job->fd.application_name),

src/bgw/scheduler.c

@@ -448,6 +448,8 @@ ts_update_scheduled_jobs_list(List *cur_jobs_list, MemoryContext mctx)
 	ListCell *new_ptr = list_head(new_jobs);
 	ListCell *cur_ptr = list_head(cur_jobs_list);
 
+	elog(DEBUG2, "updating scheduled jobs list");
+
 	while (cur_ptr != NULL && new_ptr != NULL)
 	{
 		ScheduledBgwJob *new_sjob = lfirst(new_ptr);
@@ -734,6 +736,8 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms,
 	TimestampTz start = ts_timer_get_current_timestamp();
 	TimestampTz quit_time = DT_NOEND;
 
+	log_min_messages = ts_guc_bgw_log_level;
+
 	pgstat_report_activity(STATE_RUNNING, NULL);
 
 	/* txn to read the list of jobs from the DB */
@@ -747,7 +751,7 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms,
 	if (run_for_interval_ms > 0)
 		quit_time = TimestampTzPlusMilliseconds(start, run_for_interval_ms);
 
-	ereport(DEBUG1, (errmsg("database scheduler starting for database %u", MyDatabaseId)));
+	elog(DEBUG1, "database scheduler for database %u starting", MyDatabaseId);
 
 	/*
 	 * on SIGTERM the process will usually die from the CHECK_FOR_INTERRUPTS
@@ -775,6 +779,7 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms,
 		{
 			got_SIGHUP = false;
 			ProcessConfigFile(PGC_SIGHUP);
+			log_min_messages = ts_guc_bgw_log_level;
 		}
 
 		/*
@@ -798,6 +803,8 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms,
 		MemoryContextReset(scratch_mctx);
 	}
 
+	elog(DEBUG1, "database scheduler for database %u exiting", MyDatabaseId);
+
 #ifdef TS_DEBUG
 	if (ts_shutdown_bgw)
 		elog(WARNING, "bgw scheduler stopped due to shutdown_bgw guc");
@@ -863,6 +870,7 @@ ts_bgw_scheduler_register_signal_handlers(void)
 	/* Some SIGHUPS may already have been dropped, so we must load the file here */
 	got_SIGHUP = false;
 	ProcessConfigFile(PGC_SIGHUP);
+	log_min_messages = ts_guc_bgw_log_level;
 }
 
 Datum

src/guc.c

@@ -63,6 +63,14 @@ static const struct config_enum_entry dist_copy_transfer_formats[] = {
 	{ NULL, 0, false }
 };
 
+/* Copied from contrib/auto_explain/auto_explain.c */
+static const struct config_enum_entry loglevel_options[] = {
+	{ "debug5", DEBUG5, false }, { "debug4", DEBUG4, false }, { "debug3", DEBUG3, false },
+	{ "debug2", DEBUG2, false }, { "debug1", DEBUG1, false }, { "debug", DEBUG2, true },
+	{ "info", INFO, false },	 { "notice", NOTICE, false }, { "warning", WARNING, false },
+	{ "log", LOG, false },		 { NULL, 0, false }
+};
+
 bool ts_guc_enable_deprecation_warnings = true;
 bool ts_guc_enable_optimizations = true;
 bool ts_guc_restoring = false;
@@ -86,6 +94,7 @@ bool ts_guc_enable_async_append = true;
 bool ts_guc_enable_chunkwise_aggregation = true;
 TSDLLEXPORT bool ts_guc_enable_compression_indexscan = true;
 TSDLLEXPORT bool ts_guc_enable_bulk_decompression = true;
+TSDLLEXPORT int ts_guc_bgw_log_level;
 TSDLLEXPORT bool ts_guc_enable_skip_scan = true;
 /* default value of ts_guc_max_open_chunks_per_insert and ts_guc_max_cached_chunks_per_hypertable
  * will be set as their respective boot-value when the GUC mechanism starts up */
@@ -713,6 +722,18 @@ _guc_init(void)
 							   /* assign_hook= */ NULL,
 							   /* show_hook= */ NULL);
 
+	DefineCustomEnumVariable("timescaledb.bgw_log_level",
+							 "Log level for the background worker subsystem",
+							 "Log level for the scheduler and workers of the background worker "
+							 "subsystem. Requires configuration reload to change.",
+							 /* valueAddr= */ &ts_guc_bgw_log_level,
+							 /* bootValue= */ log_min_messages,
+							 /* options= */ loglevel_options,
+							 /* context= */ PGC_SIGHUP,
+							 0,
+							 NULL,
+							 NULL,
+							 NULL);
 #ifdef USE_TELEMETRY
 	DefineCustomStringVariable(/* name= */ "timescaledb_telemetry.cloud",
 							   /* short_desc= */ "cloud provider",

src/guc.h

@@ -64,6 +64,7 @@ extern TSDLLEXPORT char *ts_guc_passfile;
 extern TSDLLEXPORT bool ts_guc_enable_remote_explain;
 extern TSDLLEXPORT bool ts_guc_enable_compression_indexscan;
 extern TSDLLEXPORT bool ts_guc_enable_bulk_decompression;
+extern TSDLLEXPORT int ts_guc_bgw_log_level;
 
 typedef enum DataFetcherType
 {

test/src/bgw/log.c

@@ -76,10 +76,6 @@ emit_log_hook_callback(ErrorData *edata)
 	if (MyProc == NULL)
 		return;
 
-	/* We are only interested in elevel LOG and above. */
-	if (edata->elevel < LOG)
-		return;
-
 	/*
 	 * Block signals so we don't lose messages generated during signal
 	 * processing if they occur while we are saving this log message (since