Re: Query hitting empty tables taking 48 minutes

From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
To: Robert Creager <robert(at)logicalchaos(dot)org>
Cc: pgsql-general(at)postgresql(dot)org, Robert Creager <robertc(at)spectralogic(dot)com>
Subject: Re: Query hitting empty tables taking 48 minutes
Date: 2018-06-07 21:34:55
Message-ID: 6299.1528407295@sss.pgh.pa.us
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-general

Robert Creager <robert(at)logicalchaos(dot)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

In response to

Responses

Browse pgsql-general by date

  From Date Subject
Next Message pinker 2018-06-07 21:44:04 Re: inner join elimination
Previous Message Tom Lane 2018-06-07 20:57:36 Code of Conduct committee: call for volunteers