Re: Query hitting empty tables taking 48 minutes - Mailing list pgsql-general

On Jun 7, 2018, at 3:34 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Robert Creager <robert@logicalchaos.org> writes:

Jun  7 17:24:21 blackpearl postgres[10670]: [7737-1] db=tapesystem,user=Administrator,app=[unknown],client=127.0.0.1 LOG:  duration: 2903612.206 ms  execute fetch from S_2037436/C_2037437: SELECT * FROM ds3.blob WHERE EXISTS (SELECT * FROM ds3.job_entry WHERE blob_id = ds3.blob.id AND (job_id = $1))

tapesystem=# explain analyze SELECT * FROM ds3.blob WHERE EXISTS (SELECT * FROM ds3.job_entry WHERE blob_id = ds3.blob.id AND (job_id = 'b51357cd-e07a-4c87-a50b-999c347a5c71'));                       
                                                             QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------                                                                
Nested Loop  (cost=0.84..6.89 rows=1 width=77) (actual time=0.044..0.044 rows=0 loops=1)
  ->  Index Scan using job_entry_job_id_idx on job_entry  (cost=0.42..2.44 rows=1 width=16) (actual time=0.042..0.042 rows=0 loops=1)
        Index Cond: (job_id = 'b51357cd-e07a-4c87-a50b-999c347a5c71'::uuid)
  ->  Index Scan using blob_pkey on blob  (cost=0.42..4.44 rows=1 width=77) (never executed)
        Index Cond: (id = job_entry.blob_id)                                  
Planning time: 0.388 ms
Execution time: 0.118 ms                                                                                                                                                               

That's fairly bizarre, but important to notice here is that you don't have
an apples-to-apples comparison.  The query in the log is evidently
parameterized, whereas your EXPLAIN isn't; it's got a hard-wired constant
to compare to job_id.  I'd suggest trying this in psql:

PREPARE foo(uuid) AS SELECT * FROM ds3.blob WHERE EXISTS (SELECT * FROM ds3.job_entry WHERE blob_id = ds3.blob.id AND (job_id = $1));

EXPLAIN ANALYZE EXECUTE foo('b51357cd-e07a-4c87-a50b-999c347a5c71');

Assuming you get a sane plan the first time, repeat the EXPLAIN ANALYZE
half a dozen times, and note whether the plan changes after six
executions.  (The point here is to see if the plancache will shift to
a "generic" plan, and if so whether that's worse than a "custom" plan
for the specific parameter value.)

If the job_id column has fairly uniform statistics, this exercise
probably won't turn up anything surprising ... but if it doesn't,
we might find that the issue comes from a stupidly chosen generic
plan.

regards, tom lane