diff --git a/.unreleased/feature_5876 b/.unreleased/feature_5876 new file mode 100644 index 00000000000..5c5306244e6 --- /dev/null +++ b/.unreleased/feature_5876 @@ -0,0 +1 @@ +Implements: #5876 Add execution time for jobs to log diff --git a/src/bgw/job.c b/src/bgw/job.c index 3947a748078..29ef4b2a029 100644 --- a/src/bgw/job.c +++ b/src/bgw/job.c @@ -25,6 +25,7 @@ #include #include #include +#include #include #include #include @@ -1175,6 +1176,8 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) BgwJob *job; JobResult res = JOB_FAILURE; bool got_lock; + instr_time start; + instr_time duration; memcpy(¶ms, MyBgworkerEntry->bgw_extra, sizeof(BgwParams)); Ensure(params.user_oid != 0 && params.job_id != 0, @@ -1196,6 +1199,8 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) ts_license_enable_module_loading(); + INSTR_TIME_SET_CURRENT(start); + StartTransactionCommand(); /* Grab a session lock on the job row to prevent concurrent deletes. Lock is released * when the job process exits */ @@ -1270,11 +1275,18 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) pfree(job); } + INSTR_TIME_SET_CURRENT(duration); + INSTR_TIME_SUBTRACT(duration, start); + /* * the rethrow will log the error; but also log which job threw the * error */ - elog(LOG, "job %d threw an error", params.job_id); + elog(LOG, + "exiting job %d (%s) with error: execution time %.2fms", + params.job_id, + NameStr(job->fd.application_name), + INSTR_TIME_GET_MILLISEC(duration)); ErrorData *edata; FormData_job_error jerr = { 0 }; @@ -1316,17 +1328,22 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) CommitTransactionCommand(); + INSTR_TIME_SET_CURRENT(duration); + INSTR_TIME_SUBTRACT(duration, start); + + elog(LOG, + "exiting job %d (%s) with %s: execution time %.2fms", + params.job_id, + NameStr(job->fd.application_name), + (res == JOB_SUCCESS ? "success" : "failure"), + INSTR_TIME_GET_MILLISEC(duration)); + if (job != NULL) { pfree(job); job = NULL; } - elog(DEBUG1, - "exiting job %d with %s", - params.job_id, - (res == JOB_SUCCESS ? "success" : "failure")); - PG_RETURN_VOID(); } diff --git a/src/cross_module_fn.c b/src/cross_module_fn.c index a59a4027f68..2e4aebab6ef 100644 --- a/src/cross_module_fn.c +++ b/src/cross_module_fn.c @@ -19,10 +19,7 @@ #define CROSSMODULE_WRAPPER(func) \ TS_FUNCTION_INFO_V1(ts_##func); \ - Datum ts_##func(PG_FUNCTION_ARGS) \ - { \ - PG_RETURN_DATUM(ts_cm_functions->func(fcinfo)); \ - } + Datum ts_##func(PG_FUNCTION_ARGS) { PG_RETURN_DATUM(ts_cm_functions->func(fcinfo)); } /* bgw policy functions */ CROSSMODULE_WRAPPER(policy_compression_add); diff --git a/tsl/test/expected/bgw_db_scheduler.out b/tsl/test/expected/bgw_db_scheduler.out index a9219895b67..0658d7ca567 100644 --- a/tsl/test/expected/bgw_db_scheduler.out +++ b/tsl/test/expected/bgw_db_scheduler.out @@ -96,7 +96,10 @@ CREATE TABLE public.bgw_log( msg TEXT ); CREATE VIEW sorted_bgw_log AS - SELECT msg_no, application_name, regexp_replace(regexp_replace(msg, 'Wait until [0-9]+, started at [0-9]+', 'Wait until (RANDOM), started at (RANDOM)'), 'background worker "[^"]+"','connection') AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT ); @@ -202,13 +205,14 @@ SELECT * FROM timescaledb_information.job_stats; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+------------------------------------------------------------------------ 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | unscheduled | Execute job 1 -(4 rows) + 1 | unscheduled | exiting job 1000 (unscheduled) with success: execution time (RANDOM)ms +(5 rows) SELECT delete_job(1000); delete_job @@ -312,12 +316,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(3 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(4 rows) --Test that the scheduler will not run job again if not enough time has passed SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); @@ -334,13 +339,14 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) -(4 rows) +(5 rows) --After enough time has passed the scheduler will run the job again SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100, 50); @@ -357,17 +363,19 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(8 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(10 rows) --Now it runs it one more time SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(120, 100); @@ -384,21 +392,24 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(12 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(15 rows) -- -- Test what happens when running a job that throws an error @@ -718,13 +729,14 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(4 rows) + 2 | test_job_3_long | exiting job 1003 (test_job_3_long) with success: execution time (RANDOM)ms +(5 rows) SELECT ts_bgw_params_mock_wait_returns_immediately(:WAIT_ON_JOB); ts_bgw_params_mock_wait_returns_immediately @@ -805,8 +817,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 @@ -817,7 +829,8 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(10 rows) + 2 | test_job_3_long | exiting job 1004 (test_job_3_long) with success: execution time (RANDOM)ms +(11 rows) --Test sending a SIGHUP to a job \c :TEST_DBNAME :ROLE_SUPERUSER @@ -982,8 +995,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) @@ -995,7 +1008,8 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(11 rows) + 2 | test_job_3_long | exiting job 1005 (test_job_3_long) with success: execution time (RANDOM)ms +(12 rows) CREATE FUNCTION wait_for_timer_to_run(started_at INTEGER, spins INTEGER=:TEST_SPINWAIT_ITERS) RETURNS BOOLEAN LANGUAGE PLPGSQL AS $BODY$ @@ -1191,12 +1205,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 -(3 rows) + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms +(4 rows) -- Now just make sure that the job actually runs in 200ms SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(200); @@ -1215,16 +1230,18 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 -(7 rows) + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms +(9 rows) -- Test updating jobs list TRUNCATE bgw_log; @@ -1572,25 +1589,29 @@ SELECT ts_bgw_params_reset_time(500000, true); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+-------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 + 1 | another | exiting job 1024 (another) with success: execution time (RANDOM)ms 3 | DB Scheduler | [TESTING] Registered new background worker 4 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 + 1 | another | exiting job 1024 (another) with success: execution time (RANDOM)ms 5 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 6 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 7 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 8 | DB Scheduler | [TESTING] Registered new background worker 9 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 + 1 | new_job | exiting job 1025 (new_job) with success: execution time (RANDOM)ms 10 | DB Scheduler | [TESTING] Registered new background worker 11 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 -(16 rows) + 1 | new_job | exiting job 1025 (new_job) with success: execution time (RANDOM)ms +(20 rows) \x on SELECT * FROM _timescaledb_internal.bgw_job_stat; diff --git a/tsl/test/expected/bgw_db_scheduler_fixed.out b/tsl/test/expected/bgw_db_scheduler_fixed.out index 36924390e2c..a9601411e19 100644 --- a/tsl/test/expected/bgw_db_scheduler_fixed.out +++ b/tsl/test/expected/bgw_db_scheduler_fixed.out @@ -100,9 +100,10 @@ CREATE TABLE public.bgw_log( msg TEXT ); CREATE VIEW sorted_bgw_log AS - SELECT msg_no, application_name, - regexp_replace(regexp_replace(msg, 'Wait until [0-9]+, started at [0-9]+', 'Wait until (RANDOM), started at (RANDOM)'), 'background worker "[^"]+"','connection') - AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT ); @@ -195,13 +196,14 @@ SELECT * FROM timescaledb_information.job_stats; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+------------------------------------------------------------------------ 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | unscheduled | Execute job 1 -(4 rows) + 1 | unscheduled | exiting job 1000 (unscheduled) with success: execution time (RANDOM)ms +(5 rows) SELECT delete_job(1000); delete_job @@ -311,12 +313,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(3 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(4 rows) --Test that the scheduler will not run job again if not enough time has passed SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); @@ -333,13 +336,14 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) -(4 rows) +(5 rows) --After enough time has passed the scheduler will run the job again SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100, 50); @@ -356,17 +360,19 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(8 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(10 rows) --Now it runs it one more time SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(120, 100); @@ -383,21 +389,24 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 -(12 rows) + 1 | test_job_1 | exiting job 1000 (test_job_1) with success: execution time (RANDOM)ms +(15 rows) -- -- Test what happens when running a job that throws an error @@ -718,13 +727,14 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(4 rows) + 2 | test_job_3_long | exiting job 1003 (test_job_3_long) with success: execution time (RANDOM)ms +(5 rows) SELECT ts_bgw_params_mock_wait_returns_immediately(:WAIT_ON_JOB); ts_bgw_params_mock_wait_returns_immediately @@ -805,8 +815,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 @@ -817,7 +827,8 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(10 rows) + 2 | test_job_3_long | exiting job 1004 (test_job_3_long) with success: execution time (RANDOM)ms +(11 rows) --Test sending a SIGHUP to a job \c :TEST_DBNAME :ROLE_SUPERUSER @@ -982,8 +993,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) @@ -995,7 +1006,8 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 -(11 rows) + 2 | test_job_3_long | exiting job 1005 (test_job_3_long) with success: execution time (RANDOM)ms +(12 rows) CREATE FUNCTION wait_for_timer_to_run(started_at INTEGER, spins INTEGER=:TEST_SPINWAIT_ITERS) RETURNS BOOLEAN LANGUAGE PLPGSQL AS $BODY$ @@ -1191,12 +1203,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 -(3 rows) + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms +(4 rows) -- Now just make sure that the job actually runs in 200ms SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(200); @@ -1215,16 +1228,18 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 -(7 rows) + 1 | test_job_4 | exiting job 1012 (test_job_4) with success: execution time (RANDOM)ms +(9 rows) -- Test updating jobs list TRUNCATE bgw_log; @@ -1558,25 +1573,29 @@ SELECT ts_bgw_params_reset_time(500000, true); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+---------------------------------------------------- + msg_no | application_name | msg +--------+------------------+-------------------------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 + 1 | another | exiting job 1024 (another) with success: execution time (RANDOM)ms 3 | DB Scheduler | [TESTING] Registered new background worker 4 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 + 1 | another | exiting job 1024 (another) with success: execution time (RANDOM)ms 5 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 6 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 7 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 8 | DB Scheduler | [TESTING] Registered new background worker 9 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 + 1 | new_job | exiting job 1025 (new_job) with success: execution time (RANDOM)ms 10 | DB Scheduler | [TESTING] Registered new background worker 11 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 -(16 rows) + 1 | new_job | exiting job 1025 (new_job) with success: execution time (RANDOM)ms +(20 rows) SELECT * FROM _timescaledb_internal.bgw_job_stat; job_id | last_start | last_finish | next_start | last_successful_finish | last_run_success | total_runs | total_duration | total_duration_failures | total_successes | total_failures | total_crashes | consecutive_failures | consecutive_crashes | flags diff --git a/tsl/test/expected/bgw_reorder_drop_chunks.out b/tsl/test/expected/bgw_reorder_drop_chunks.out index a3fea4b6d2a..9f68e495fe3 100644 --- a/tsl/test/expected/bgw_reorder_drop_chunks.out +++ b/tsl/test/expected/bgw_reorder_drop_chunks.out @@ -34,11 +34,8 @@ CREATE VIEW sorted_bgw_log AS SELECT msg_no, mock_time, application_name, - CASE WHEN length(msg) > 80 THEN - substring(msg, 1, 80) || '...' - ELSE - msg - END AS msg + regexp_replace(CASE WHEN length(msg) > 80 THEN substring(msg, 1, 80) || '...' ELSE msg END, + '(execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g') AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", @@ -131,11 +128,12 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+-------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 -(2 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-----------------------+---------------------------------------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms +(3 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -169,13 +167,15 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+---------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 -(4 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-----------------------+---------------------------------------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 25000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms +(6 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -211,15 +211,18 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(50); -- job info is gone SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+----------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 -(6 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-----------------------+---------------------------------------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 25000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 + 0 | 50000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms +(9 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -254,16 +257,19 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+------------------------------------------------ - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 - 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 -(7 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-----------------------+---------------------------------------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 25000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 + 0 | 50000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 +(10 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -323,17 +329,20 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(125); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+------------------------------------------------ - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 - 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 - 0 | 200000 | DB Scheduler | [TESTING] Wait until 325000, started at 200000 -(8 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-----------------------+---------------------------------------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 25000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 + 0 | 50000 | Reorder Policy [1000] | exiting job 1000 (Reorder Policy [1000]) with success: execution time (RANDOM)ms + 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 + 0 | 200000 | DB Scheduler | [TESTING] Wait until 325000, started at 200000 +(11 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -447,11 +456,12 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+-------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 -(2 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-------------------------+------------------------------------------------------------------------------------ + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Retention Policy [1001] | exiting job 1001 (Retention Policy [1001]) with success: execution time (RANDOM)ms +(3 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -485,12 +495,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+---------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 -(3 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-------------------------+------------------------------------------------------------------------------------ + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Retention Policy [1001] | exiting job 1001 (Retention Policy [1001]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 +(4 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -534,15 +545,17 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(10000); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+------------------+--------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 50000 | DB Scheduler | [TESTING] Wait until 1000000, started at 50000 - 1 | 1000000 | DB Scheduler | [TESTING] Registered new background worker - 2 | 1000000 | DB Scheduler | [TESTING] Wait until 10050000, started at 1000000 -(6 rows) + msg_no | mock_time | application_name | msg +--------+-----------+-------------------------+------------------------------------------------------------------------------------ + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 0 | Retention Policy [1001] | exiting job 1001 (Retention Policy [1001]) with success: execution time (RANDOM)ms + 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 50000 | DB Scheduler | [TESTING] Wait until 1000000, started at 50000 + 1 | 1000000 | DB Scheduler | [TESTING] Registered new background worker + 2 | 1000000 | DB Scheduler | [TESTING] Wait until 10050000, started at 1000000 + 0 | 1000000 | Retention Policy [1001] | exiting job 1001 (Retention Policy [1001]) with success: execution time (RANDOM)ms +(8 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -655,9 +668,11 @@ SELECT * FROM sorted_bgw_log; 1 | 0 | DB Scheduler | [TESTING] Registered new background worker 2 | 0 | DB Scheduler | [TESTING] Wait until 1000000, started at 0 0 | 0 | Retention Policy [1002] | applying retention policy to hypertable "test_drop_chunks_table_date": dropping ... + 1 | 0 | Retention Policy [1002] | exiting job 1002 (Retention Policy [1002]) with success: execution time (RANDOM)ms 0 | 0 | Retention Policy [1003] | applying retention policy to hypertable "test_drop_chunks_table_tsntz": dropping... + 1 | 0 | Retention Policy [1003] | exiting job 1003 (Retention Policy [1003]) with success: execution time (RANDOM)ms 0 | 1000000 | DB Scheduler | [TESTING] Wait until 2000000, started at 1000000 -(6 rows) +(8 rows) -- test the schedule_interval parameter for policies CREATE TABLE test_schedint(time timestamptz, a int, b int); diff --git a/tsl/test/expected/cagg_bgw.out b/tsl/test/expected/cagg_bgw.out index c2250ec0513..8f433a56aa0 100644 --- a/tsl/test/expected/cagg_bgw.out +++ b/tsl/test/expected/cagg_bgw.out @@ -46,7 +46,11 @@ CREATE TABLE public.bgw_log( msg TEXT ); CREATE VIEW sorted_bgw_log AS - SELECT * FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + mock_time, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT ); @@ -74,14 +78,14 @@ SELECT * FROM _timescaledb_catalog.continuous_agg; -- though user on access node has required GRANTS, this will propagate GRANTS to the connected data nodes GRANT CREATE ON SCHEMA public TO :ROLE_DEFAULT_PERM_USER; -psql:include/cagg_bgw_common.sql:72: WARNING: no privileges were granted for "public" +psql:include/cagg_bgw_common.sql:76: WARNING: no privileges were granted for "public" \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER CREATE TABLE test_continuous_agg_table(time int, data int); \if :IS_DISTRIBUTED SELECT create_distributed_hypertable('test_continuous_agg_table', 'time', chunk_time_interval => 10, replication_factor => 2); \else SELECT create_hypertable('test_continuous_agg_table', 'time', chunk_time_interval => 10); -psql:include/cagg_bgw_common.sql:78: NOTICE: adding not-null constraint to column "time" +psql:include/cagg_bgw_common.sql:82: NOTICE: adding not-null constraint to column "time" create_hypertable ---------------------------------------- (1,public,test_continuous_agg_table,t) @@ -155,12 +159,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+----------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1000] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -2147483648, 6 ] -(3 rows) + 1 | 0 | Refresh Continuous Aggregate Policy [1000] | exiting job 1000 (Refresh Continuous Aggregate Policy [1000]) with success: execution time (RANDOM)ms +(4 rows) SELECT * FROM _timescaledb_config.bgw_job where id=:job_id; id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | initial_start | hypertable_id | config | check_schema | check_name | timezone @@ -366,7 +371,7 @@ SELECT ts_bgw_params_reset_time(); (1 row) DROP MATERIALIZED VIEW test_continuous_agg_view; -psql:include/cagg_bgw_common.sql:230: NOTICE: drop cascades to table _timescaledb_internal._hyper_2_3_chunk +psql:include/cagg_bgw_common.sql:234: NOTICE: drop cascades to table _timescaledb_internal._hyper_2_3_chunk CREATE MATERIALIZED VIEW test_continuous_agg_view WITH (timescaledb.continuous, timescaledb.materialized_only=true) @@ -388,12 +393,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+---------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] -(3 rows) + 1 | 0 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms +(4 rows) -- job ran once, successfully SELECT job_id, last_finish - next_start as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes @@ -433,15 +439,17 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+---------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] + 1 | 0 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 43200000000 | DB Scheduler | [TESTING] Wait until 43200025000, started at 43200000000 + 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] -(6 rows) + 1 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms +(8 rows) SELECT job_id, next_start - last_finish as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes FROM _timescaledb_internal.bgw_job_stat @@ -493,7 +501,7 @@ last_run_duration | \x off DROP MATERIALIZED VIEW test_continuous_agg_view; -psql:include/cagg_bgw_common.sql:290: NOTICE: drop cascades to table _timescaledb_internal._hyper_3_4_chunk +psql:include/cagg_bgw_common.sql:294: NOTICE: drop cascades to table _timescaledb_internal._hyper_3_4_chunk --create a view with a function that it has no permission to execute CREATE MATERIALIZED VIEW test_continuous_agg_view WITH (timescaledb.continuous, @@ -559,7 +567,7 @@ CREATE TABLE test_continuous_agg_table_w_grant(time int, data int); SELECT create_distributed_hypertable('test_continuous_agg_table_w_grant', 'time', chunk_time_interval => 10, replication_factor => 2); \else SELECT create_hypertable('test_continuous_agg_table_w_grant', 'time', chunk_time_interval => 10); -psql:include/cagg_bgw_common.sql:328: NOTICE: adding not-null constraint to column "time" +psql:include/cagg_bgw_common.sql:332: NOTICE: adding not-null constraint to column "time" create_hypertable ------------------------------------------------ (5,public,test_continuous_agg_table_w_grant,t) @@ -661,16 +669,17 @@ SELECT * FROM test_continuous_agg_view_user_2; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT * from sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------ + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1003] | refreshing continuous aggregate "test_continuous_agg_view_user_2" in window [ -2147483648, 2 ] + 1 | 0 | Refresh Continuous Aggregate Policy [1003] | exiting job 1003 (Refresh Continuous Aggregate Policy [1003]) with success: execution time (RANDOM)ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 43200000000 | DB Scheduler | [TESTING] Wait until 43200025000, started at 43200000000 + 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | job 1003 threw an error 1 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | permission denied for table test_continuous_agg_table_w_grant -(7 rows) +(8 rows) -- Count the number of continuous aggregate policies SELECT count(*) FROM _timescaledb_config.bgw_job diff --git a/tsl/test/expected/cagg_bgw_dist_ht.out b/tsl/test/expected/cagg_bgw_dist_ht.out index b1b2186441f..5150720a9e0 100644 --- a/tsl/test/expected/cagg_bgw_dist_ht.out +++ b/tsl/test/expected/cagg_bgw_dist_ht.out @@ -83,7 +83,11 @@ CREATE TABLE public.bgw_log( msg TEXT ); CREATE VIEW sorted_bgw_log AS - SELECT * FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + mock_time, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT ); @@ -111,12 +115,12 @@ SELECT * FROM _timescaledb_catalog.continuous_agg; -- though user on access node has required GRANTS, this will propagate GRANTS to the connected data nodes GRANT CREATE ON SCHEMA public TO :ROLE_DEFAULT_PERM_USER; -psql:include/cagg_bgw_common.sql:72: WARNING: no privileges were granted for "public" +psql:include/cagg_bgw_common.sql:76: WARNING: no privileges were granted for "public" \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER CREATE TABLE test_continuous_agg_table(time int, data int); \if :IS_DISTRIBUTED SELECT create_distributed_hypertable('test_continuous_agg_table', 'time', chunk_time_interval => 10, replication_factor => 2); -psql:include/cagg_bgw_common.sql:76: NOTICE: adding not-null constraint to column "time" +psql:include/cagg_bgw_common.sql:80: NOTICE: adding not-null constraint to column "time" create_distributed_hypertable ---------------------------------------- (1,public,test_continuous_agg_table,t) @@ -192,12 +196,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+----------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1000] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -2147483648, 6 ] -(3 rows) + 1 | 0 | Refresh Continuous Aggregate Policy [1000] | exiting job 1000 (Refresh Continuous Aggregate Policy [1000]) with success: execution time (RANDOM)ms +(4 rows) SELECT * FROM _timescaledb_config.bgw_job where id=:job_id; id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | initial_start | hypertable_id | config | check_schema | check_name | timezone @@ -403,7 +408,7 @@ SELECT ts_bgw_params_reset_time(); (1 row) DROP MATERIALIZED VIEW test_continuous_agg_view; -psql:include/cagg_bgw_common.sql:230: NOTICE: drop cascades to table _timescaledb_internal._hyper_2_3_chunk +psql:include/cagg_bgw_common.sql:234: NOTICE: drop cascades to table _timescaledb_internal._hyper_2_3_chunk CREATE MATERIALIZED VIEW test_continuous_agg_view WITH (timescaledb.continuous, timescaledb.materialized_only=true) @@ -425,12 +430,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+---------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] -(3 rows) + 1 | 0 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms +(4 rows) -- job ran once, successfully SELECT job_id, last_finish - next_start as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes @@ -470,15 +476,17 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+---------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] + 1 | 0 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 43200000000 | DB Scheduler | [TESTING] Wait until 43200025000, started at 43200000000 + 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] -(6 rows) + 1 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | exiting job 1001 (Refresh Continuous Aggregate Policy [1001]) with success: execution time (RANDOM)ms +(8 rows) SELECT job_id, next_start - last_finish as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes FROM _timescaledb_internal.bgw_job_stat @@ -530,7 +538,7 @@ last_run_duration | \x off DROP MATERIALIZED VIEW test_continuous_agg_view; -psql:include/cagg_bgw_common.sql:290: NOTICE: drop cascades to table _timescaledb_internal._hyper_3_4_chunk +psql:include/cagg_bgw_common.sql:294: NOTICE: drop cascades to table _timescaledb_internal._hyper_3_4_chunk --create a view with a function that it has no permission to execute CREATE MATERIALIZED VIEW test_continuous_agg_view WITH (timescaledb.continuous, @@ -594,7 +602,7 @@ SELECT ts_bgw_params_reset_time(); CREATE TABLE test_continuous_agg_table_w_grant(time int, data int); \if :IS_DISTRIBUTED SELECT create_distributed_hypertable('test_continuous_agg_table_w_grant', 'time', chunk_time_interval => 10, replication_factor => 2); -psql:include/cagg_bgw_common.sql:326: NOTICE: adding not-null constraint to column "time" +psql:include/cagg_bgw_common.sql:330: NOTICE: adding not-null constraint to column "time" create_distributed_hypertable ------------------------------------------------ (5,public,test_continuous_agg_table_w_grant,t) @@ -698,16 +706,17 @@ SELECT * FROM test_continuous_agg_view_user_2; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT * from sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------ + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1003] | refreshing continuous aggregate "test_continuous_agg_view_user_2" in window [ -2147483648, 2 ] + 1 | 0 | Refresh Continuous Aggregate Policy [1003] | exiting job 1003 (Refresh Continuous Aggregate Policy [1003]) with success: execution time (RANDOM)ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 43200000000 | DB Scheduler | [TESTING] Wait until 43200025000, started at 43200000000 + 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | job 1003 threw an error 1 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | permission denied for table test_continuous_agg_table_w_grant -(7 rows) +(8 rows) -- Count the number of continuous aggregate policies SELECT count(*) FROM _timescaledb_config.bgw_job diff --git a/tsl/test/sql/bgw_db_scheduler.sql b/tsl/test/sql/bgw_db_scheduler.sql index c621b95c259..c58e8a12b15 100644 --- a/tsl/test/sql/bgw_db_scheduler.sql +++ b/tsl/test/sql/bgw_db_scheduler.sql @@ -112,7 +112,10 @@ CREATE TABLE public.bgw_log( ); CREATE VIEW sorted_bgw_log AS - SELECT msg_no, application_name, regexp_replace(regexp_replace(msg, 'Wait until [0-9]+, started at [0-9]+', 'Wait until (RANDOM), started at (RANDOM)'), 'background worker "[^"]+"','connection') AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT diff --git a/tsl/test/sql/bgw_db_scheduler_fixed.sql b/tsl/test/sql/bgw_db_scheduler_fixed.sql index 9a7c3621a25..5fb53c6e2ca 100644 --- a/tsl/test/sql/bgw_db_scheduler_fixed.sql +++ b/tsl/test/sql/bgw_db_scheduler_fixed.sql @@ -116,9 +116,10 @@ CREATE TABLE public.bgw_log( ); CREATE VIEW sorted_bgw_log AS - SELECT msg_no, application_name, - regexp_replace(regexp_replace(msg, 'Wait until [0-9]+, started at [0-9]+', 'Wait until (RANDOM), started at (RANDOM)'), 'background worker "[^"]+"','connection') - AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT diff --git a/tsl/test/sql/bgw_reorder_drop_chunks.sql b/tsl/test/sql/bgw_reorder_drop_chunks.sql index b7b7893e8bc..bb5a7e03bbd 100644 --- a/tsl/test/sql/bgw_reorder_drop_chunks.sql +++ b/tsl/test/sql/bgw_reorder_drop_chunks.sql @@ -45,11 +45,8 @@ CREATE VIEW sorted_bgw_log AS SELECT msg_no, mock_time, application_name, - CASE WHEN length(msg) > 80 THEN - substring(msg, 1, 80) || '...' - ELSE - msg - END AS msg + regexp_replace(CASE WHEN length(msg) > 80 THEN substring(msg, 1, 80) || '...' ELSE msg END, + '(execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g') AS msg FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", @@ -363,4 +360,4 @@ select ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(40000); select total_runs, total_successes, total_failures from timescaledb_information.job_stats where job_id = :polcomp_schedint; -- if we wait another 40s, we should see 3 runs of the job select ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(40000); -select total_runs, total_successes, total_failures from timescaledb_information.job_stats where job_id = :polcomp_schedint; \ No newline at end of file +select total_runs, total_successes, total_failures from timescaledb_information.job_stats where job_id = :polcomp_schedint; diff --git a/tsl/test/sql/include/cagg_bgw_common.sql b/tsl/test/sql/include/cagg_bgw_common.sql index da9077c2feb..31cfbc465d4 100644 --- a/tsl/test/sql/include/cagg_bgw_common.sql +++ b/tsl/test/sql/include/cagg_bgw_common.sql @@ -56,7 +56,11 @@ CREATE TABLE public.bgw_log( ); CREATE VIEW sorted_bgw_log AS - SELECT * FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + SELECT msg_no, + mock_time, + application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; CREATE TABLE public.bgw_dsm_handle_store( handle BIGINT