Date: Wed, 6 Oct 2021 14:20:00 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: "Dirschel, Steve" <steve.dirschel@thomsonreuters.com>
Cc: pgsql-performance@lists.postgresql.org
Subject: Re: Troubleshooting a long running delete statement
Message-ID: <20211006192000.GJ27491@telsasoft.com>
References: 
 <DM6PR03MB43323A813F2489B43B50195AFAB09@DM6PR03MB4332.namprd03.prod.outlook.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: 
 <DM6PR03MB43323A813F2489B43B50195AFAB09@DM6PR03MB4332.namprd03.prod.outlook.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Archived-At: 
 <https://www.postgresql.org/message-id/20211006192000.GJ27491%40telsasoft.com>
Precedence: bulk

On Wed, Oct 06, 2021 at 06:00:07PM +0000, Dirschel, Steve wrote:
> •       When I did an explain on the delete I could see it was full scanning the table. I did a full scan of the table interactively in less than 1 second so the long runtime was not due to the full tablescan.

> I started looking at table definitions (indexes, FK's, etc.) and comparing to Oracle and noticed some indexes missing.  I then could see the table being deleted from was a child table with a FK pointing to a parent table.  Finally I was able to see that the parent table was missing an index on the FK column so for every row being deleted from the child it was full scanning the parent.  All makes sense after the fact but I'm looking for a more methodical way to come to that conclusion by looking at database statistics.
> 
> Are there other statistics in Postgres I may have looked at to methodically come to the conclusion that the problem was the missing index on the parent FK column?

I think explain (analyze on) would've helped you.

If I understand your scenario, it'd look like this:

|postgres=# explain (analyze) delete from t;
| Delete on t  (cost=0.00..145.00 rows=10000 width=6) (actual time=10.124..10.136 rows=0 loops=1)
|   ->  Seq Scan on t  (cost=0.00..145.00 rows=10000 width=6) (actual time=0.141..2.578 rows=10000 loops=1)
| Planning Time: 0.484 ms
| Trigger for constraint u_i_fkey: time=4075.123 calls=10000
| Execution Time: 4087.764 ms

You can see the query plan used for the FK trigger with autoexplain.

postgres=*# SET auto_explain.log_min_duration='0s'; SET client_min_messages=debug; SET auto_explain.log_nested_statements=on;
postgres=*# explain (analyze) delete from t;
|...
|Query Text: DELETE FROM ONLY "public"."u" WHERE $1 OPERATOR(pg_catalog.=) "i"
|Delete on u  (cost=0.00..214.00 rows=1 width=6) (actual rows=0 loops=1)
|  Buffers: shared hit=90
|  ->  Seq Scan on u  (cost=0.00..214.00 rows=1 width=6) (actual rows=1 loops=1)
|        Filter: ($1 = i)
|        Rows Removed by Filter: 8616
|        Buffers: shared hit=89
|...