citusdata / pg_cron

Run periodic jobs in PostgreSQL
PostgreSQL License
2.89k stars 193 forks source link

Misleading start times in pg_cron 1.6.3 #342

Closed esiaero closed 3 months ago

esiaero commented 3 months ago

Starting in pg_cron 1.6.3, the start times reported for jobs seems to be slightly off.

Snippet of this behavior, tested on 16.3

postgres=> SHOW cron.max_running_jobs;
 cron.max_running_jobs 
-----------------------
 1
(1 row)

postgres=> SELECT * from cron.job_run_details ORDER by start_time desc LIMIT 4;
 jobid | runid | job_pid | database | username |      command       |  status   | return_message |          start_time           |           end_time            
-------+-------+---------+----------+----------+--------------------+-----------+----------------+-------------------------------+-------------------------------
     3 |    15 |    1146 | postgres | foo      | SELECT pg_sleep(5) | succeeded | 1 row          | 2024-07-31 01:19:04.010878+00 | 2024-07-31 01:19:10.01683+00
     4 |    14 |    1037 | postgres | foo      | SELECT pg_sleep(5) | succeeded | 1 row          | 2024-07-31 01:19:00.000452+00 | 2024-07-31 01:19:05.008552+00
     3 |    13 |     382 | postgres | foo      | SELECT pg_sleep(5) | succeeded | 1 row          | 2024-07-31 01:18:04.011246+00 | 2024-07-31 01:18:10.021891+00
     4 |    12 |   32742 | postgres | foo      | SELECT pg_sleep(5) | succeeded | 1 row          | 2024-07-31 01:18:00.000994+00 | 2024-07-31 01:18:05.011994+00
(4 rows)

Despite max_running_jobs being 1, the start/end times suggests that these jobs are overlapping. I think the cause is this commit - https://github.com/citusdata/pg_cron/commit/d90843de92d5e517a23b1e17da56dc08c496c774, which changes the reported start time, but not the actual job start.

Wondering if this change in behavior was intended?

spencerbryson commented 3 months ago

+1

Can confirm reverting d90843de92d5e517a23b1e17da56dc08c496c774 restores the original behaviour.

marcoslot commented 3 months ago

Thanks, pushed a revert.