Slow queries with many finished entries and concurrency control

[til]

On a system with a lot of entries in the good_jobs table for finished jobs (around 700k) and only a few thousand of them being unfinished, I'm seeing that a specific query is being executed many times and takes many seconds to finish.

Below is the plan of that query, reproduced with dummy values for its bind variables. It took around 14s:

motiontag_production=> explain analyze SELECT "good_jobs"."active_job_id" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "good_jobs"."concurrency_key" = 'User-abc' AND "pg_locks"."locktype" IS NOT NULL ORDER BY COALESCE(performed_at, scheduled_at, created_at) ASC LIMIT 1;
                                                                                                                                                          QUERY PLAN                                                                                                                                                           
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=58819.16..58819.17 rows=1 width=24) (actual time=14476.154..14476.239 rows=0 loops=1)
   ->  Sort  (cost=58819.16..58819.17 rows=1 width=24) (actual time=14476.153..14476.237 rows=0 loops=1)
         Sort Key: (COALESCE(good_jobs.performed_at, good_jobs.scheduled_at, good_jobs.created_at))
         Sort Method: quicksort  Memory: 25kB
         ->  Nested Loop  (cost=1000.00..58819.15 rows=1 width=24) (actual time=14476.146..14476.231 rows=0 loops=1)
               Join Filter: (((((('x'::text || substr(md5(('good_jobs-'::text || (good_jobs.active_job_id)::text)), 1, 16)))::bit(32))::integer)::oid = l.classid) AND ((((((('x'::text || substr(md5(('good_jobs-'::text || (good_jobs.active_job_id)::text)), 1, 16)))::bit(64) << 32))::bit(32))::integer)::oid = l.objid))
               ->  Function Scan on pg_lock_status l  (cost=0.00..15.00 rows=1 width=8) (actual time=2.143..2.241 rows=20 loops=1)
                     Filter: ((locktype IS NOT NULL) AND (locktype = 'advisory'::text) AND (objsubid = 1))
                     Rows Removed by Filter: 291
               ->  Gather  (cost=1000.00..58800.23 rows=56 width=40) (actual time=723.693..723.698 rows=0 loops=20)
                     Workers Planned: 2
                     Workers Launched: 0
                     ->  Parallel Seq Scan on good_jobs  (cost=0.00..57794.63 rows=23 width=40) (actual time=643.763..643.764 rows=0 loops=49)
                           Filter: (concurrency_key = 'User-abc'::text)
                           Rows Removed by Filter: 291213
 Planning Time: 0.326 ms
 Execution Time: 14476.308 ms

The table has an index on the concurrency_key but limited to the condition WHERE finished_at IS NULL. Is this the code that triggers this query: https://github.com/bensheldon/good_job/blob/main/lib/good_job/active_job_extensions/concurrency.rb#L64-L68? If yes, is there a reason why this query is not limited to the unfinished scope? Modified to include finished_at IS NULL, it would use the index and run a lot faster:

motiontag_production=> explain analyze SELECT "good_jobs"."active_job_id" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE finished_at IS NULL and "good_jobs"."concurrency_key" = 'User-abc' AND "pg_locks"."locktype" IS NOT NULL ORDER BY COALESCE(performed_at, scheduled_at, created_at) ASC LIMIT 1;
                                                                                                                                                          QUERY PLAN                                                                                                                                                           
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=23.50..23.51 rows=1 width=24) (actual time=0.020..0.021 rows=0 loops=1)
   ->  Sort  (cost=23.50..23.51 rows=1 width=24) (actual time=0.019..0.020 rows=0 loops=1)
         Sort Key: (COALESCE(good_jobs.performed_at, good_jobs.scheduled_at, good_jobs.created_at))
         Sort Method: quicksort  Memory: 25kB
         ->  Nested Loop  (cost=0.41..23.49 rows=1 width=24) (actual time=0.016..0.016 rows=0 loops=1)
               Join Filter: (((((('x'::text || substr(md5(('good_jobs-'::text || (good_jobs.active_job_id)::text)), 1, 16)))::bit(32))::integer)::oid = l.classid) AND ((((((('x'::text || substr(md5(('good_jobs-'::text || (good_jobs.active_job_id)::text)), 1, 16)))::bit(64) << 32))::bit(32))::integer)::oid = l.objid))
               ->  Index Scan using index_good_jobs_on_concurrency_key_when_unfinished on good_jobs  (cost=0.41..8.42 rows=1 width=40) (actual time=0.015..0.016 rows=0 loops=1)
                     Index Cond: (concurrency_key = 'User-abc'::text)
               ->  Function Scan on pg_lock_status l  (cost=0.00..15.00 rows=1 width=8) (never executed)
                     Filter: ((locktype IS NOT NULL) AND (locktype = 'advisory'::text) AND (objsubid = 1))
 Planning Time: 0.295 ms
 Execution Time: 0.064 ms

[bensheldon]

@til thank you! Thank looks like the correct analysis to me. I think the reason why I initially didn't use unfinished is that there is not an atomic operation of "mark-as-finished and unlock". But thinking about it now, I think it likely does not matter...and the performance benefit you've highlighted is significant.

[bensheldon]

@til I just released v2.9.6 with that PR. Please give it a try.

[til]

Works well now, thanks for the quick release!