Very slow DELETEs with foreign keys

Hi,

I've just noticed a general delete performance issue while testing a
patch, and this can be recreated on all recent major versions.

I have 2 tables:

CREATE TABLE countries (
    country text PRIMARY KEY,
    continent text
);

CREATE TABLE contacts (
    id serial PRIMARY KEY,
    first_name text,
    last_name text,
    age integer,
    country text REFERENCES countries (country)
);


Here's a sample of the data in the tables:

# SELECT * FROM contacts LIMIT 10;
   id    | first_name | last_name  | age |             country
---------+------------+------------+-----+----------------------------------
 4873919 | Sharon     | Blackburn  |  45 | Indonesia
 4873920 | Ila        | Merrill    |   3 | Zambia
 4873921 | Brian      | Rogers     |  85 | Bahamas
 4873922 | Michelle   | Cunningham |  33 | Malta
 4873923 | Garrett    | Thompson   |  17 | France
 4873924 | Jemima     | Holloway   |  57 | Bahamas
 4873925 | Hector     | Walls      |  82 | Kenya
 4873926 | Evangeline | Copeland   |  57 | Isle of Man
 4873927 | Montana    | Cline      |   9 | Saint Vincent and The Grenadines
 4873928 | Reece      | Albert     |  66 | Virgin Islands, United States
(10 rows)


# SELECT * FROM countries LIMIT 10;
  country   |   continent
------------+---------------
 Albania    | Europe
 Algeria    | Africa
 Andorra    | Europe
 Angola     | Africa
 Anguilla   | Caribbean
 Antarctica | Antarctica
 Argentina  | South America
 Armenia    | Europe
 Aruba      | Caribbean
 Australia  | Australasia
(10 rows)

"contacts" contains 5 million rows
"countries" contains 498 rows


I then ran:

INSERT INTO countries
SELECT country || '1', continent || '2' FROM countries;

to duplicate all the rows, but with a number appended to the values.

But ran into a problem with:

# DELETE FROM countries WHERE continent LIKE '%2';
^CCancel request sent
ERROR:  canceling statement due to user request
CONTEXT:  SQL statement "SELECT 1 FROM ONLY "public"."contacts" x
WHERE $1 OPERATOR(pg_catalog.=) "country" FOR KEY SHARE OF x"
Time: 278560.623 ms

As you can see, I ran out of patience, but before I did, I ran a stack trace:

#0  ExecScan (node=node@entry=0x1a97f40,
accessMtd=accessMtd@entry=0x661063 <SeqNext>,
recheckMtd=recheckMtd@entry=0x661050 <SeqRecheck>) at execScan.c:236
#1  0x000000000066118b in ExecSeqScan (node=node@entry=0x1a97f40) at
nodeSeqscan.c:127
#2  0x000000000063ba4a in ExecProcNode (node=node@entry=0x1a97f40) at
execProcnode.c:419
#3  0x0000000000658860 in ExecLockRows (node=node@entry=0x1a97d50) at
nodeLockRows.c:57
#4  0x000000000063bd67 in ExecProcNode (node=node@entry=0x1a97d50) at
execProcnode.c:527
#5  0x0000000000636363 in ExecutePlan (estate=estate@entry=0x1a97b70,
planstate=0x1a97d50, use_parallel_mode=0 '\000',
operation=operation@entry=CMD_SELECT,
    sendTuples=sendTuples@entry=1 '\001',
numberTuples=numberTuples@entry=1,
direction=direction@entry=ForwardScanDirection,
dest=dest@entry=0xde70c0 <spi_printtupDR>)
    at execMain.c:1566
#6  0x00000000006372ac in standard_ExecutorRun (queryDesc=0x1aadbf0,
direction=ForwardScanDirection, count=1) at execMain.c:338
#7  0x0000000000637350 in ExecutorRun
(queryDesc=queryDesc@entry=0x1aadbf0,
direction=direction@entry=ForwardScanDirection, count=count@entry=1)
at execMain.c:286
#8  0x000000000066cdcf in _SPI_pquery
(queryDesc=queryDesc@entry=0x1aadbf0,
fire_triggers=fire_triggers@entry=0 '\000', tcount=1) at spi.c:2404
#9  0x000000000066f7a3 in _SPI_execute_plan
(plan=plan@entry=0x1aad790, paramLI=0x1aadba0,
snapshot=snapshot@entry=0x0,
    crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000', tcount=tcount@entry=1)
    at spi.c:2192
#10 0x000000000066fcc8 in SPI_execute_snapshot
(plan=plan@entry=0x1aad790, Values=Values@entry=0x7ffff20c8e80,
Nulls=Nulls@entry=0x7ffff20c8e40 " ",
    snapshot=snapshot@entry=0x0,
crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000',
    tcount=tcount@entry=1) at spi.c:489
#11 0x0000000000873f1b in ri_PerformCheck
(riinfo=riinfo@entry=0x1a7cb70, qkey=qkey@entry=0x7ffff20c9360,
qplan=0x1aad790, fk_rel=fk_rel@entry=0x7fcdcde65480,
    pk_rel=pk_rel@entry=0x7fcdcde5ee88,
old_tuple=old_tuple@entry=0x7ffff20c9940,
new_tuple=new_tuple@entry=0x0, detectNewRows=detectNewRows@entry=1
'\001',
    expect_OK=expect_OK@entry=5) at ri_triggers.c:3142
#12 0x00000000008746e7 in ri_restrict_del (trigdata=<optimized out>,
is_no_action=is_no_action@entry=1 '\001') at ri_triggers.c:773
#13 0x0000000000875b07 in RI_FKey_noaction_del (fcinfo=0x7ffff20c9510)
at ri_triggers.c:613
#14 0x00000000006118f0 in ExecCallTriggerFunc
(trigdata=trigdata@entry=0x7ffff20c9960, tgindx=tgindx@entry=0,
finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
    per_tuple_context=per_tuple_context@entry=0x1aa5c50) at trigger.c:1910
#15 0x0000000000612fae in AfterTriggerExecute
(event=event@entry=0x1a7cea0, rel=rel@entry=0x7fcdcde5ee88,
trigdesc=trigdesc@entry=0x1a01490,
    finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
per_tuple_context=per_tuple_context@entry=0x1aa5c50,
trig_tuple_slot1=trig_tuple_slot1@entry=0x0,
    trig_tuple_slot2=trig_tuple_slot2@entry=0x0) at trigger.c:3643
#16 0x00000000006132b3 in afterTriggerInvokeEvents
(events=events@entry=0x1a8d8a0, firing_id=1,
estate=estate@entry=0x1a01240, delete_ok=delete_ok@entry=1 '\001')
    at trigger.c:3836
#17 0x0000000000618134 in AfterTriggerEndQuery
(estate=estate@entry=0x1a01240) at trigger.c:4008
#18 0x00000000006373d2 in standard_ExecutorFinish
(queryDesc=0x1ab33d0) at execMain.c:411
#19 0x0000000000637449 in ExecutorFinish
(queryDesc=queryDesc@entry=0x1ab33d0) at execMain.c:379
#20 0x00000000007af5c6 in ProcessQuery (plan=plan@entry=0x1aaa3b8,
sourceText=0x1a4dda0 "delete from countries where continent like
'%2';", params=0x0,
    dest=dest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:225
#21 0x00000000007af73d in PortalRunMulti
(portal=portal@entry=0x1aa7720, isTopLevel=isTopLevel@entry=1 '\001',
dest=dest@entry=0x1aaa498,
    altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:1275
#22 0x00000000007b077e in PortalRun (portal=portal@entry=0x1aa7720,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=1
'\001',
    dest=dest@entry=0x1aaa498, altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:812
#23 0x00000000007ad433 in exec_simple_query
(query_string=query_string@entry=0x1a4dda0 "delete from countries
where continent like '%2';") at postgres.c:1094
#24 0x00000000007ae029 in PostgresMain (argc=<optimized out>,
argv=argv@entry=0x19e7b98, dbname=0x19e7a48 "postgres",
username=<optimized out>) at postgres.c:4021
#25 0x0000000000730091 in BackendRun (port=port@entry=0x1a08150) at
postmaster.c:4258
#26 0x000000000073272c in BackendStartup (port=port@entry=0x1a08150)
at postmaster.c:3932
#27 0x0000000000732af2 in ServerLoop () at postmaster.c:1690
#28 0x00000000007345c1 in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x19e6c70) at postmaster.c:1298
#29 0x0000000000689943 in main (argc=3, argv=0x19e6c70) at main.c:223

Then another:

#0  ExecQual (qual=qual@entry=0x1a98b60,
econtext=econtext@entry=0x1a98050, resultForNull=resultForNull@entry=0
'\000') at execQual.c:5263
#1  0x0000000000645821 in ExecScan (node=node@entry=0x1a97f40,
accessMtd=accessMtd@entry=0x661063 <SeqNext>,
recheckMtd=recheckMtd@entry=0x661050 <SeqRecheck>)
    at execScan.c:208
#2  0x000000000066118b in ExecSeqScan (node=node@entry=0x1a97f40) at
nodeSeqscan.c:127
#3  0x000000000063ba4a in ExecProcNode (node=node@entry=0x1a97f40) at
execProcnode.c:419
#4  0x0000000000658860 in ExecLockRows (node=node@entry=0x1a97d50) at
nodeLockRows.c:57
#5  0x000000000063bd67 in ExecProcNode (node=node@entry=0x1a97d50) at
execProcnode.c:527
#6  0x0000000000636363 in ExecutePlan (estate=estate@entry=0x1a97b70,
planstate=0x1a97d50, use_parallel_mode=0 '\000',
operation=operation@entry=CMD_SELECT,
    sendTuples=sendTuples@entry=1 '\001',
numberTuples=numberTuples@entry=1,
direction=direction@entry=ForwardScanDirection,
dest=dest@entry=0xde70c0 <spi_printtupDR>)
    at execMain.c:1566
#7  0x00000000006372ac in standard_ExecutorRun (queryDesc=0x1aadbf0,
direction=ForwardScanDirection, count=1) at execMain.c:338
#8  0x0000000000637350 in ExecutorRun
(queryDesc=queryDesc@entry=0x1aadbf0,
direction=direction@entry=ForwardScanDirection, count=count@entry=1)
at execMain.c:286
#9  0x000000000066cdcf in _SPI_pquery
(queryDesc=queryDesc@entry=0x1aadbf0,
fire_triggers=fire_triggers@entry=0 '\000', tcount=1) at spi.c:2404
#10 0x000000000066f7a3 in _SPI_execute_plan
(plan=plan@entry=0x1aad790, paramLI=0x1aadba0,
snapshot=snapshot@entry=0x0,
    crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000', tcount=tcount@entry=1)
    at spi.c:2192
#11 0x000000000066fcc8 in SPI_execute_snapshot
(plan=plan@entry=0x1aad790, Values=Values@entry=0x7ffff20c8e80,
Nulls=Nulls@entry=0x7ffff20c8e40 " ",
    snapshot=snapshot@entry=0x0,
crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000',
    tcount=tcount@entry=1) at spi.c:489
#12 0x0000000000873f1b in ri_PerformCheck
(riinfo=riinfo@entry=0x1a7cb70, qkey=qkey@entry=0x7ffff20c9360,
qplan=0x1aad790, fk_rel=fk_rel@entry=0x7fcdcde65480,
    pk_rel=pk_rel@entry=0x7fcdcde5ee88,
old_tuple=old_tuple@entry=0x7ffff20c9940,
new_tuple=new_tuple@entry=0x0, detectNewRows=detectNewRows@entry=1
'\001',
    expect_OK=expect_OK@entry=5) at ri_triggers.c:3142
#13 0x00000000008746e7 in ri_restrict_del (trigdata=<optimized out>,
is_no_action=is_no_action@entry=1 '\001') at ri_triggers.c:773
#14 0x0000000000875b07 in RI_FKey_noaction_del (fcinfo=0x7ffff20c9510)
at ri_triggers.c:613
#15 0x00000000006118f0 in ExecCallTriggerFunc
(trigdata=trigdata@entry=0x7ffff20c9960, tgindx=tgindx@entry=0,
finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
    per_tuple_context=per_tuple_context@entry=0x1aa5c50) at trigger.c:1910
#16 0x0000000000612fae in AfterTriggerExecute
(event=event@entry=0x1a7ceb8, rel=rel@entry=0x7fcdcde5ee88,
trigdesc=trigdesc@entry=0x1a01490,
    finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
per_tuple_context=per_tuple_context@entry=0x1aa5c50,
trig_tuple_slot1=trig_tuple_slot1@entry=0x0,
    trig_tuple_slot2=trig_tuple_slot2@entry=0x0) at trigger.c:3643
#17 0x00000000006132b3 in afterTriggerInvokeEvents
(events=events@entry=0x1a8d8a0, firing_id=1,
estate=estate@entry=0x1a01240, delete_ok=delete_ok@entry=1 '\001')
    at trigger.c:3836
#18 0x0000000000618134 in AfterTriggerEndQuery
(estate=estate@entry=0x1a01240) at trigger.c:4008
#19 0x00000000006373d2 in standard_ExecutorFinish
(queryDesc=0x1ab33d0) at execMain.c:411
#20 0x0000000000637449 in ExecutorFinish
(queryDesc=queryDesc@entry=0x1ab33d0) at execMain.c:379
#21 0x00000000007af5c6 in ProcessQuery (plan=plan@entry=0x1aaa3b8,
sourceText=0x1a4dda0 "delete from countries where continent like
'%2';", params=0x0,
    dest=dest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:225
#22 0x00000000007af73d in PortalRunMulti
(portal=portal@entry=0x1aa7720, isTopLevel=isTopLevel@entry=1 '\001',
dest=dest@entry=0x1aaa498,
    altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:1275
#23 0x00000000007b077e in PortalRun (portal=portal@entry=0x1aa7720,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=1
'\001',
    dest=dest@entry=0x1aaa498, altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:812
#24 0x00000000007ad433 in exec_simple_query
(query_string=query_string@entry=0x1a4dda0 "delete from countries
where continent like '%2';") at postgres.c:1094
#25 0x00000000007ae029 in PostgresMain (argc=<optimized out>,
argv=argv@entry=0x19e7b98, dbname=0x19e7a48 "postgres",
username=<optimized out>) at postgres.c:4021
#26 0x0000000000730091 in BackendRun (port=port@entry=0x1a08150) at
postmaster.c:4258
#27 0x000000000073272c in BackendStartup (port=port@entry=0x1a08150)
at postmaster.c:3932
#28 0x0000000000732af2 in ServerLoop () at postmaster.c:1690
#29 0x00000000007345c1 in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x19e6c70) at postmaster.c:1298
#30 0x0000000000689943 in main (argc=3, argv=0x19e6c70) at main.c:223

Then another:

#0  SeqNext (node=node@entry=0x1a97f40) at nodeSeqscan.c:62
#1  0x00000000006457a6 in ExecScanFetch (recheckMtd=0x661050
<SeqRecheck>, accessMtd=0x661063 <SeqNext>, node=0x1a97f40) at
execScan.c:95
#2  ExecScan (node=node@entry=0x1a97f40,
accessMtd=accessMtd@entry=0x661063 <SeqNext>,
recheckMtd=recheckMtd@entry=0x661050 <SeqRecheck>) at execScan.c:180
#3  0x000000000066118b in ExecSeqScan (node=node@entry=0x1a97f40) at
nodeSeqscan.c:127
#4  0x000000000063ba4a in ExecProcNode (node=node@entry=0x1a97f40) at
execProcnode.c:419
#5  0x0000000000658860 in ExecLockRows (node=node@entry=0x1a97d50) at
nodeLockRows.c:57
#6  0x000000000063bd67 in ExecProcNode (node=node@entry=0x1a97d50) at
execProcnode.c:527
#7  0x0000000000636363 in ExecutePlan (estate=estate@entry=0x1a97b70,
planstate=0x1a97d50, use_parallel_mode=0 '\000',
operation=operation@entry=CMD_SELECT,
    sendTuples=sendTuples@entry=1 '\001',
numberTuples=numberTuples@entry=1,
direction=direction@entry=ForwardScanDirection,
dest=dest@entry=0xde70c0 <spi_printtupDR>)
    at execMain.c:1566
#8  0x00000000006372ac in standard_ExecutorRun (queryDesc=0x1aadbf0,
direction=ForwardScanDirection, count=1) at execMain.c:338
#9  0x0000000000637350 in ExecutorRun
(queryDesc=queryDesc@entry=0x1aadbf0,
direction=direction@entry=ForwardScanDirection, count=count@entry=1)
at execMain.c:286
#10 0x000000000066cdcf in _SPI_pquery
(queryDesc=queryDesc@entry=0x1aadbf0,
fire_triggers=fire_triggers@entry=0 '\000', tcount=1) at spi.c:2404
#11 0x000000000066f7a3 in _SPI_execute_plan
(plan=plan@entry=0x1aad790, paramLI=0x1aadba0,
snapshot=snapshot@entry=0x0,
    crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000', tcount=tcount@entry=1)
    at spi.c:2192
#12 0x000000000066fcc8 in SPI_execute_snapshot
(plan=plan@entry=0x1aad790, Values=Values@entry=0x7ffff20c8e80,
Nulls=Nulls@entry=0x7ffff20c8e40 " ",
    snapshot=snapshot@entry=0x0,
crosscheck_snapshot=crosscheck_snapshot@entry=0x0,
read_only=read_only@entry=0 '\000',
fire_triggers=fire_triggers@entry=0 '\000',
    tcount=tcount@entry=1) at spi.c:489
#13 0x0000000000873f1b in ri_PerformCheck
(riinfo=riinfo@entry=0x1a7cb70, qkey=qkey@entry=0x7ffff20c9360,
qplan=0x1aad790, fk_rel=fk_rel@entry=0x7fcdcde65480,
    pk_rel=pk_rel@entry=0x7fcdcde5ee88,
old_tuple=old_tuple@entry=0x7ffff20c9940,
new_tuple=new_tuple@entry=0x0, detectNewRows=detectNewRows@entry=1
'\001',
    expect_OK=expect_OK@entry=5) at ri_triggers.c:3142
#14 0x00000000008746e7 in ri_restrict_del (trigdata=<optimized out>,
is_no_action=is_no_action@entry=1 '\001') at ri_triggers.c:773
#15 0x0000000000875b07 in RI_FKey_noaction_del (fcinfo=0x7ffff20c9510)
at ri_triggers.c:613
#16 0x00000000006118f0 in ExecCallTriggerFunc
(trigdata=trigdata@entry=0x7ffff20c9960, tgindx=tgindx@entry=0,
finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
    per_tuple_context=per_tuple_context@entry=0x1aa5c50) at trigger.c:1910
#17 0x0000000000612fae in AfterTriggerExecute
(event=event@entry=0x1a7d050, rel=rel@entry=0x7fcdcde5ee88,
trigdesc=trigdesc@entry=0x1a01490,
    finfo=finfo@entry=0x1a01630, instr=instr@entry=0x0,
per_tuple_context=per_tuple_context@entry=0x1aa5c50,
trig_tuple_slot1=trig_tuple_slot1@entry=0x0,
    trig_tuple_slot2=trig_tuple_slot2@entry=0x0) at trigger.c:3643
#18 0x00000000006132b3 in afterTriggerInvokeEvents
(events=events@entry=0x1a8d8a0, firing_id=1,
estate=estate@entry=0x1a01240, delete_ok=delete_ok@entry=1 '\001')
    at trigger.c:3836
#19 0x0000000000618134 in AfterTriggerEndQuery
(estate=estate@entry=0x1a01240) at trigger.c:4008
#20 0x00000000006373d2 in standard_ExecutorFinish
(queryDesc=0x1ab33d0) at execMain.c:411
#21 0x0000000000637449 in ExecutorFinish
(queryDesc=queryDesc@entry=0x1ab33d0) at execMain.c:379
#22 0x00000000007af5c6 in ProcessQuery (plan=plan@entry=0x1aaa3b8,
sourceText=0x1a4dda0 "delete from countries where continent like
'%2';", params=0x0,
    dest=dest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:225
#23 0x00000000007af73d in PortalRunMulti
(portal=portal@entry=0x1aa7720, isTopLevel=isTopLevel@entry=1 '\001',
dest=dest@entry=0x1aaa498,
    altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:1275
#24 0x00000000007b077e in PortalRun (portal=portal@entry=0x1aa7720,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=1
'\001',
    dest=dest@entry=0x1aaa498, altdest=altdest@entry=0x1aaa498,
completionTag=completionTag@entry=0x7ffff20c9d20 "DELETE 249") at
pquery.c:812
#25 0x00000000007ad433 in exec_simple_query
(query_string=query_string@entry=0x1a4dda0 "delete from countries
where continent like '%2';") at postgres.c:1094
#26 0x00000000007ae029 in PostgresMain (argc=<optimized out>,
argv=argv@entry=0x19e7b98, dbname=0x19e7a48 "postgres",
username=<optimized out>) at postgres.c:4021
#27 0x0000000000730091 in BackendRun (port=port@entry=0x1a08150) at
postmaster.c:4258
#28 0x000000000073272c in BackendStartup (port=port@entry=0x1a08150)
at postmaster.c:3932
#29 0x0000000000732af2 in ServerLoop () at postmaster.c:1690
#30 0x00000000007345c1 in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x19e6c70) at postmaster.c:1298
#31 0x0000000000689943 in main (argc=3, argv=0x19e6c70) at main.c:223


I was curious how long this would take to run to completion, and it
turned out to be 5m 8s.

This is just trying to delete rows from a table which aren't
referenced by any rows on the other end of the foreign key constraint.

So what this is doing is, for each country matched, it's running a
query on the contacts table like so:

SELECT 1 FROM ONLY "public"."contacts" x WHERE 'Albania1'
OPERATOR(pg_catalog.=) "country" FOR KEY SHARE OF x;

This individual query takes 850ms, and it has to do this 249 times (as
it will only match half the table because of LIKE '%2'.

Is there something that can be done to improve this?  If the
referenced table had tens of thousands of rows in, the query might as
well never complete.  Even with an index, it still requires running a
query for every matched row in the referenced table.

Thom