Re: Query hitting empty tables taking 48 minutes

Robert Creager wrote:
> A different query started showing up as the problem, the auto_explain with analyze shows an oddity,
> the total query duration is 11k seconds, while the query itself is 3 seconds. I captured a ZFS
> snapshot as soon as the problem was noticed.
>
> db=tapesystem,user=Administrator,app=[unknown],client=127.0.0.1 LOG: duration: 10856644.336 ms plan:
> Query Text: DELETE FROM ds3.blob WHERE EXISTS (SELECT * FROM ds3.s3_object WHERE id = ds3.blob.object_id AND (bucket_id = $1))
> Delete on blob (cost=1308.79..1312.82 rows=1 width=12) (actual time=3465.919..3465.919 rows=0 loops=1)
> [...]
>
> Doing a ZFS rollback and executing the query shows what is happening, although not to the extent above.
> If I read this correctly, it’s the constraint checks that are causing the query to take so long.
> I don’t see any server configuration that might allow those checks to be parallelized. Is that possible?
>
> tapesystem=# PREPARE foo(uuid) AS DELETE FROM ds3.blob WHERE EXISTS (SELECT * FROM ds3.s3_object WHERE id = ds3.blob.object_id AND (bucket_id = $1)); EXPLAIN ANALYZE EXECUTE foo('bc6e6b10-80ad-4329-9fb9-1a66d8c1505e');
> PREPARE

Are we missing an "EXECUTE foo('bc6e6b10-80ad-4329-9fb9-1a66d8c1505e')" here?

> QUERY PLAN
> --------------------------------------------------------------------------------------------------------------------------------
> Delete on blob (cost=9555.07..21134.01 rows=299993 width=12) (actual time=1516.140..1516.140 rows=0 loops=1)
> [...]
> Trigger for constraint blob_tape_blob_id_fkey: time=5389.627 calls=300000
> Trigger for constraint multi_part_upload_placeholder_blob_id_fkey: time=4566.305 calls=300000
> Trigger for constraint multi_part_upload_part_blob_id_fkey: time=3597.896 calls=300000
> Trigger for constraint blob_pool_blob_id_fkey: time=4631.851 calls=300000
> Trigger for constraint blob_target_blob_id_fkey: time=4688.731 calls=300000
> Trigger for constraint suspect_blob_tape_blob_id_fkey: time=4473.787 calls=300000
> Trigger for constraint suspect_blob_pool_blob_id_fkey: time=4475.286 calls=300000
> Trigger for constraint suspect_blob_target_blob_id_fkey: time=4353.237 calls=300000
> Trigger for constraint blob_s3_target_blob_id_fkey: time=4451.687 calls=300000
> Trigger for constraint blob_azure_target_blob_id_fkey: time=4448.613 calls=300000
> Trigger for constraint suspect_blob_azure_target_blob_id_fkey: time=4353.467 calls=300000
> Execution time: 85175.581 ms
>
> I executed a vacuum analyze, then a vacuum full analyze, neither changed the timing.
> Other than removing constraints, is there any way to address this?

I cannot explain the discrepancy between the runtimes of 85 seconds versus 10857 seconds.

But other than that, it sure looks like the foreign keys are missing an index on
the source columns, leading to a sequential scan for each deletion and table.

Yours,
Laurenz Albe
--
Cybertec | https://www.cybertec-postgresql.com