Re: Query hitting empty tables taking 48 minutes

> On Jun 7, 2018, at 3:34 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>
> 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.)

The plan didn’t change after bunches (> 6) executions.

tapesystem=# EXPLAIN ANALYZE EXECUTE foo('b51357cd-e07a-4c87-a50b-999c347a5c71');
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.84..6.89 rows=1 width=77) (actual time=0.032..0.032 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.031..0.031 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)
Execution time: 0.096 ms
(6 rows)

Executing with the job_id shown in the stats of the empty table below (didn’t change after bunches of executions). The job_entry table has very ephemeral data in general.

tapesystem=# EXPLAIN ANALYZE EXECUTE foo('cc54ca5d-0dca-4b35-acd9-e0fe69c6b247');
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------
Hash Join (cost=9582.63..21191.13 rows=300019 width=77) (actual time=22.679..22.679 rows=0 loops=1)
Hash Cond: (job_entry.blob_id = blob.id)
-> Seq Scan on job_entry (cost=0.00..7483.24 rows=300019 width=16) (actual time=22.677..22.677 rows=0 loops=1)
Filter: (job_id = 'cc54ca5d-0dca-4b35-acd9-e0fe69c6b247'::uuid)
-> Hash (cost=5832.28..5832.28 rows=300028 width=77) (never executed)
-> Seq Scan on blob (cost=0.00..5832.28 rows=300028 width=77) (never executed)
Execution time: 22.723 ms

>
> 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.

If it’s helpful, via https://www.postgresql.org/docs/9.6/static/planner-stats.html: <https://www.postgresql.org/docs/9.6/static/planner-stats.html:>

tapesystem=# SELECT relname, relkind, reltuples, relpages FROM pg_class WHERE relname LIKE 'job_entry%';
relname | relkind | reltuples | relpages
------------------------------------+---------+-----------+----------
job_entry | r | 300021 | 3733
job_entry_blob_id_idx | i | 300022 | 1509
job_entry_chunk_id_idx | i | 300022 | 1405
job_entry_job_id_blob_id_key | i | 300022 | 2392
job_entry_job_id_idx | i | 300022 | 1424
job_entry_order_index_chunk_id_key | i | 300022 | 1971
job_entry_pkey | i | 300022 | 1528

tapesystem=# SELECT attname, inherited, n_distinct, array_to_string(most_common_vals, E'\n') as most_common_vals FROM pg_stats WHERE tablename = 'job_entry';
attname | inherited | n_distinct | most_common_vals
-------------+-----------+------------+--------------------------------------
blob_id | f | -1 |
chunk_id | f | 15 | 800a4923-d567-4227-a7fb-a882f601b48e+
| | | d024bb7e-7dc8-4d02-b756-08ee1002961e+
| | | 2993eb2f-5350-4904-ab6c-a4e7f8ab0956+
| | | 9f0776c9-82ba-444e-8d18-e910270b0316+
| | | 893b860c-4ca3-487a-a36d-ac9d0cac3037+
| | | 8704b622-4d20-4ebb-9eec-ea6bb135e4dc+
| | | 5dd12960-66eb-4eba-9d84-65223802bc23+
| | | 4cb360fe-80f8-40b6-ba99-5c91d6709052+
| | | 17ee55d3-b607-42e1-9f5f-bd3ad4bc3055+
| | | 140d5b3c-b20a-4a69-9bfc-a5eb7cea07cf+
| | | 4a4a7782-749e-4954-98dd-bfc065066f1f+
| | | ea276309-a8d5-4633-98e7-4934f716f24f+
| | | dbc1e05c-32fd-4368-ae99-ce502909f9dd+
| | | b6eef3b0-9468-4682-b556-422c57c36e9e+
| | | a468960c-aadc-439f-8f52-dce1525a52ab
id | f | -1 |
job_id | f | 1 | cc54ca5d-0dca-4b35-acd9-e0fe69c6b247
order_index | f | -1 |

>
> regards, tom lane