From: Gunther <raj@gusw.net>
Subject: EXPLAIN PLAN for DELETE CASCADE or DELETE not using pkey index
 despite EXPLAINing that it would?
To: pgsql-performance@lists.postgresql.org
Message-ID: <189c6fff-0180-8179-d059-e222ec83bb1e@gusw.net>
Date: Thu, 21 Mar 2019 15:31:42 -0400
User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:60.0) Gecko/20100101
 Thunderbird/60.5.3
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Transfer-Encoding: 7bit
Content-Language: en-US
Precedence: bulk

Hi,

I have 250 rows to delete, but they are a target to a bunch of child 
tables with foreign key on delete cascade.

EXPLAIN DELETE FROM Foo WHERE id = (SELECT fooId FROM Garbage);

shows me that it uses the nested loop by Foo_pkey index to find the 250 
items from Garbage to be deleted.

But once that starts, I see HUGE amount of read activity from the 
tablespace Foo_main that contains the Foo table, and only the Foo table, 
not the Foo_pkey, not any other index, not any other child table, not 
even the toast table for Foo is contained in that tablespace (I have the 
toast table diverted with symlinks to another volume).

I see the read activity with iostat, reading heavily at 130 MB/s for a 
long time until my burst balance is used up, then continuing to churn 
with 32 MB/s.

I also see the read activity with iotop, that tells me that it is that 
postgres backend running the DELETE query that is doing this, not some 
autovacuum nor anything else.

It looks to me that in actuality it is doing a sequential scan for each 
of the 250 rows, despite it EPLAINing to me that it was going to use 
that index.

It would really be good to know what it is churning so heavily?

I have seen some ways of using dtrace or things like that to do some 
measurement points. But I haven't seen how this is done to inspect the 
effective execution plan and where in that plan it is, i.e., which 
iteration. It would be nice if there was some way of doing a "deep 
explain plan" or even better, having an idea of the execution plan which 
the executor is actually following, and a way to report on the current 
status of work according to this plan.

How else do I figure out what causes this heavy read activity on the 
main Foo table?

This is something I might even want to contribute. For many years I am 
annoyed by this waiting for long running statement without any idea 
where it is and how much is there still to go. If I have a plan 
structure and an executor that follows the plan structure, there must be 
a way to dump it out.

The pg_stat_activity table might contain a current statement id, and 
then a superuser might ask EXPLAIN STATEMENT :statementId. Or just a 
pg_plantrace command which would dump the current plan with an 
indication of completion % of each step.

But also delete cascades and triggers should be viewable from this, they 
should be traced, I am sure that somewhere inside there is some data 
structure representing this activity and all it would take is to dump it?

regards,
-Gunther