From 80b615c70afeac2aeec80e6a741f6adfb44e6848 Mon Sep 17 00:00:00 2001 From: Harry Lascelles Date: Mon, 11 Dec 2023 13:43:05 +0000 Subject: [PATCH] Change run_at default to clock_timestamp() ## Problem Jobs enqueued in transactions can appear delayed as the default `run_at` is `now()`, which is a delayed time in a long transaction. ## Example We know that the `que_jobs` table has this column: `run_at timestamp with time zone DEFAULT now() NOT NULL,` We have some jobs that perform work, and enqueue another job. eg: ```ruby class CalculateBilling < Que::Job def run(ref) ActiveRecord::Base.transaction do calculate_stuff(ref) # Takes 30 seconds SendBillingSms.enqueue(ref) end end end ``` We then also have an alarm to check our jobs are running in a timely fashion by comparing when the job started with its `run_at`. In the scenario above, this means the `SendBillingSms` job is enqueued with `run_at` as `now()`. But, `now()` does not mean "the time on the wall" in postgres. It means "the time the transaction started". See: https://newcubator.com/blog/web/postgresql-timestamp-methods _Both now() and clock_timestamp() are PostgreSQL functions. The main difference between them is that now() adds the time at the start of the transactions, while clock_timestamp() inserts the time at the execution of the statement._ This means all of our `SendBillingSms` jobs are instantaneously "30 seconds delayed", even if they are run the split second that they are visible to workers. ## Solution We could/should change the column to have a default of `clock_timestamp()`. ie: `run_at timestamp with time zone DEFAULT clock_timestamp() NOT NULL,` This means that the intent of what the `run_at` of a job "to run now" should be is more accurate (probably, ie principle of least surprise). It also means jobs can be monitored for "delayed start" more easily and accurately. Note, we do not want to use Ruby time in a `run_at` as it may be out, even by a second or two. We also would not like to pass a `run_at` in since: 1. We'd have to do it everywhere, or monkeypatch que 2. We'd have to do a DB lookup for what that time is, which is an extra call --- lib/que/migrations.rb | 2 +- lib/que/migrations/8/down.sql | 2 ++ lib/que/migrations/8/up.sql | 2 ++ spec/que/migrations.current_schema_spec.rb | 13 +++++++++++++ spec/que/migrations.state_trigger_spec.rb | 2 +- 5 files changed, 19 insertions(+), 2 deletions(-) create mode 100644 lib/que/migrations/8/down.sql create mode 100644 lib/que/migrations/8/up.sql diff --git a/lib/que/migrations.rb b/lib/que/migrations.rb index 255ae6da..967a0291 100644 --- a/lib/que/migrations.rb +++ b/lib/que/migrations.rb @@ -4,7 +4,7 @@ module Que module Migrations # In order to ship a schema change, add the relevant up and down sql files # to the migrations directory, and bump the version here. - CURRENT_VERSION = 7 + CURRENT_VERSION = 8 class << self def migrate!(version:) diff --git a/lib/que/migrations/8/down.sql b/lib/que/migrations/8/down.sql new file mode 100644 index 00000000..4ae701da --- /dev/null +++ b/lib/que/migrations/8/down.sql @@ -0,0 +1,2 @@ +ALTER TABLE que_jobs +ALTER COLUMN run_at SET DEFAULT now(); diff --git a/lib/que/migrations/8/up.sql b/lib/que/migrations/8/up.sql new file mode 100644 index 00000000..b55e7ab1 --- /dev/null +++ b/lib/que/migrations/8/up.sql @@ -0,0 +1,2 @@ +ALTER TABLE que_jobs +ALTER COLUMN run_at SET DEFAULT clock_timestamp(); diff --git a/spec/que/migrations.current_schema_spec.rb b/spec/que/migrations.current_schema_spec.rb index e4d21384..a6d799b8 100644 --- a/spec/que/migrations.current_schema_spec.rb +++ b/spec/que/migrations.current_schema_spec.rb @@ -115,6 +115,19 @@ def assert_constraint_error(name, &block) end end + describe "que_jobs table column defaults" do + it "should make sure that the default of run_at is clock_timestamp()" do + results = Que.execute (<<~SQL) + SELECT column_default + FROM information_schema.columns + WHERE table_name = 'que_jobs' AND column_name = 'run_at'; + SQL + column_default = results.to_a.first.fetch(:column_default) + + assert_equal column_default, "clock_timestamp()" + end + end + describe "que_lockers table constraints" do let :locker_attrs do { diff --git a/spec/que/migrations.state_trigger_spec.rb b/spec/que/migrations.state_trigger_spec.rb index d7be9269..01d40f30 100644 --- a/spec/que/migrations.state_trigger_spec.rb +++ b/spec/que/migrations.state_trigger_spec.rb @@ -43,7 +43,7 @@ def assert_notification( DB.transaction do result = yield - current_time = DB.get{now.function} + current_time = DB.get{clock_timestamp.function} id ||= result run_at ||= current_time