Performance tip: ANALYZE command

[amacfie-tc]

I noticed that throughput was low even though when jobs ran they executed at normal speed. There were long gaps in between jobs so it appeared that Procrastinate workers were communicating with the database very slowly. Sure enough, the procrastinate_fetch_job_v2 function was taking a long time. Here is the output of EXPLAIN ANALYZE for the SQL statement in that function:

-[ RECORD 1 ]-------------------------
QUERY PLAN | Update on procrastinate_jobs  (cost=5.61..8.65 rows=0 width=0) (actual time=21757.774..21757.776 rows=0 loops=1)
-[ RECORD 2 ]-------------------------
QUERY PLAN |   CTE candidate
-[ RECORD 3 ]-------------------------
QUERY PLAN |     ->  Limit  (cost=5.17..5.18 rows=1 width=206) (actual time=21757.621..21757.622 rows=1 loops=1)
-[ RECORD 4 ]-------------------------
QUERY PLAN |           ->  LockRows  (cost=5.17..5.18 rows=1 width=206) (actual time=21757.619..21757.620 rows=1 loops=1)
-[ RECORD 5 ]-------------------------
QUERY PLAN |                 ->  Sort  (cost=5.17..5.17 rows=1 width=206) (actual time=21757.467..21757.467 rows=3 loops=1)
-[ RECORD 6 ]-------------------------
QUERY PLAN |                       Sort Key: jobs.priority DESC, jobs.id
-[ RECORD 7 ]-------------------------
QUERY PLAN |                       Sort Method: quicksort  Memory: 1081kB
-[ RECORD 8 ]-------------------------
QUERY PLAN |                       ->  Nested Loop Anti Join  (cost=0.75..5.16 rows=1 width=206) (actual time=7.821..21742.402 rows=6145 loops=1)
-[ RECORD 9 ]-------------------------
QUERY PLAN |                             Join Filter: ((jobs.lock IS NOT NULL) AND (earlier_jobs.id < jobs.id) AND (earlier_jobs.lock = jobs.lock))
-[ RECORD 10 ]-------------------------
QUERY PLAN |                             Rows Removed by Join Filter: 37761025
-[ RECORD 11 ]-------------------------
QUERY PLAN |                             ->  Index Scan using procrastinate_jobs_id_lock_idx_v1 on procrastinate_jobs jobs  (cost=0.38..2.58 rows=1 width=200) (actual time=2.265..13.814 rows=6145 loops=1)
-[ RECORD 12 ]-------------------------
QUERY PLAN |                                   Filter: ((status = 'todo'::procrastinate_job_status) AND ((queue_name)::text = 'worker'::text) AND ((scheduled_at IS NULL) OR (scheduled_at <= now())))
-[ RECORD 13 ]-------------------------
QUERY PLAN |                             ->  Index Scan using procrastinate_jobs_id_lock_idx_v1 on procrastinate_jobs earlier_jobs  (cost=0.38..2.57 rows=1 width=74) (actual time=0.544..3.175 rows=6145 loops=6145)
-[ RECORD 14 ]-------------------------
QUERY PLAN |                                   Filter: (status = ANY ('{todo,doing}'::procrastinate_job_status[]))
-[ RECORD 15 ]-------------------------
QUERY PLAN |   ->  Nested Loop  (cost=0.43..3.47 rows=1 width=50) (actual time=21757.649..21757.651 rows=1 loops=1)
-[ RECORD 16 ]-------------------------
QUERY PLAN |         ->  CTE Scan on candidate  (cost=0.00..0.02 rows=1 width=40) (actual time=21757.631..21757.632 rows=1 loops=1)
-[ RECORD 17 ]-------------------------
QUERY PLAN |         ->  Index Scan using procrastinate_jobs_pkey on procrastinate_jobs  (cost=0.43..3.45 rows=1 width=14) (actual time=0.015..0.015 rows=1 loops=1)
-[ RECORD 18 ]-------------------------
QUERY PLAN |               Index Cond: (id = candidate.id)
-[ RECORD 19 ]-------------------------
QUERY PLAN | Planning Time: 1.740 ms
-[ RECORD 20 ]-------------------------
QUERY PLAN | Trigger for constraint procrastinate_jobs_worker_id_fkey: time=0.627 calls=1
-[ RECORD 21 ]-------------------------
QUERY PLAN | Trigger procrastinate_trigger_status_events_update_v1: time=0.172 calls=1
-[ RECORD 22 ]-------------------------
QUERY PLAN | Execution Time: 21758.703 ms

After running ANALYZE procrastinate_jobs, everything was fast again and this was the new output:

-[ RECORD 1 ]-------------------------
QUERY PLAN | Update on procrastinate_jobs  (cost=4.82..7.86 rows=0 width=0) (actual time=2.189..2.191 rows=0 loops=1)
-[ RECORD 2 ]-------------------------
QUERY PLAN |   CTE candidate
-[ RECORD 3 ]-------------------------
QUERY PLAN |     ->  Limit  (cost=0.69..4.39 rows=1 width=207) (actual time=1.993..1.995 rows=1 loops=1)
-[ RECORD 4 ]-------------------------
QUERY PLAN |           ->  LockRows  (cost=0.69..21558.09 rows=5826 width=207) (actual time=1.992..1.993 rows=1 loops=1)
-[ RECORD 5 ]-------------------------
QUERY PLAN |                 ->  Nested Loop Anti Join  (cost=0.69..21499.83 rows=5826 width=207) (actual time=1.983..1.984 rows=1 loops=1)
-[ RECORD 6 ]-------------------------
QUERY PLAN |                       Join Filter: (jobs.lock IS NOT NULL)
-[ RECORD 7 ]-------------------------
QUERY PLAN |                       ->  Index Scan using procrastinate_jobs_priority_idx_v1 on procrastinate_jobs jobs  (cost=0.41..11151.08 rows=5826 width=201) (actual time=1.976..1.977 rows=1 loops=1)
-[ RECORD 8 ]-------------------------
QUERY PLAN |                             Filter: ((status = 'todo'::procrastinate_job_status) AND ((queue_name)::text = 'worker'::text) AND ((scheduled_at IS NULL) OR (scheduled_at <= now())))
-[ RECORD 9 ]-------------------------
QUERY PLAN |                       ->  Index Scan using procrastinate_jobs_lock_status_id_idx_v1 on procrastinate_jobs earlier_jobs  (cost=0.29..1.77 rows=1 width=75) (actual time=0.004..0.004 rows=0 loops=1)
-[ RECORD 10 ]-------------------------
QUERY PLAN |                             Index Cond: ((lock = jobs.lock) AND (id < jobs.id))
-[ RECORD 11 ]-------------------------
QUERY PLAN |                             Filter: (status = ANY ('{todo,doing}'::procrastinate_job_status[]))
-[ RECORD 12 ]-------------------------
QUERY PLAN |   ->  Nested Loop  (cost=0.43..3.47 rows=1 width=50) (actual time=2.020..2.022 rows=1 loops=1)
-[ RECORD 13 ]-------------------------
QUERY PLAN |         ->  CTE Scan on candidate  (cost=0.00..0.02 rows=1 width=40) (actual time=2.005..2.006 rows=1 loops=1)
-[ RECORD 14 ]-------------------------
QUERY PLAN |         ->  Index Scan using procrastinate_jobs_pkey on procrastinate_jobs  (cost=0.43..3.45 rows=1 width=14) (actual time=0.013..0.013 rows=1 loops=1)
-[ RECORD 15 ]-------------------------
QUERY PLAN |               Index Cond: (id = candidate.id)
-[ RECORD 16 ]-------------------------
QUERY PLAN | Planning Time: 1.147 ms
-[ RECORD 17 ]-------------------------
QUERY PLAN | Trigger for constraint procrastinate_jobs_worker_id_fkey: time=0.911 calls=1
-[ RECORD 18 ]-------------------------
QUERY PLAN | Trigger procrastinate_trigger_status_events_update_v1: time=0.347 calls=1
-[ RECORD 19 ]-------------------------
QUERY PLAN | Execution Time: 3.537 ms