Re: Query hitting empty tables taking 48 minutes

[Robert Creager <robert@xxxxxxxxxxxxxxxx>]

On Jun 7, 2018, at 3:34 PM, Tom Lane <tgl@xxxxxxxxxxxxx> wrote:

Robert Creager <robert@xxxxxxxxxxxxxxxx> 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:

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