slow delete

Les <nagylzs@xxxxxxxxx> · Tue, 15 Aug 2023 22:23:26 +0200

I have created a table called _td with about 43 000 rows. I have tried to use this as a primary key id list to delete records from my product.product_file table, but I could not do it. It uses 100% of one CPU and it takes forever. Then I changed the query to delete 100 records only, and measure the speed:
EXPLAIN (ANALYZE, COSTS, VERBOSE, BUFFERS, FORMAT JSON)
delete from product.product_file where id in (
	select pf2_id from _td limit 100
)

It still takes 11 seconds. It means  110 msec / record, and that is unacceptable.  

I'm going to post the whole query plan at the end of this email, but I would like to highlight the "Triggers" part:

    "Triggers": [
      {
        "Trigger Name": "RI_ConstraintTrigger_a_26535",
        "Constraint Name": "fk_pfft_product",
        "Relation": "product_file",
        "Time": 4.600,
        "Calls": 90
      },
      {
        "Trigger Name": "RI_ConstraintTrigger_a_26837",
        "Constraint Name": "fk_product_file_src",
        "Relation": "product_file",
        "Time": 5.795,
        "Calls": 90
      },
      {
        "Trigger Name": "RI_ConstraintTrigger_a_75463",
        "Constraint Name": "fk_pfq_src_product_file",
        "Relation": "product_file",
        "Time": 11179.429,
        "Calls": 90
      },
      {
        "Trigger Name": "_trg_002_aiu_audit_row",
        "Relation": "product_file",
        "Time": 49.410,
        "Calls": 90
      }
    ]

It seems that two foreign key constraints use 10.395 seconds out of the total 11.24 seconds. But I don't see why it takes that much?

The product.product_file table has 477 000 rows:

CREATE TABLE product.product_file (
	id uuid NOT NULL,
	c_tim timestamptz NOT NULL DEFAULT CURRENT_TIMESTAMP,
	c_uid uuid NULL,
	c_sid uuid NULL,
	m_tim timestamptz NOT NULL DEFAULT CURRENT_TIMESTAMP,
	m_uid uuid NULL,
	m_sid uuid NULL,
	product_id uuid NOT NULL,
	product_file_type_id uuid NOT NULL,
	file_id uuid NOT NULL,
	product_file_status_id uuid NOT NULL,
	dl_url text NULL,
	src_product_file_id uuid NULL,
	CONSTRAINT product_file_pkey PRIMARY KEY (id),
	CONSTRAINT fk_pf_file FOREIGN KEY (file_id) REFERENCES media.file(id),
	CONSTRAINT fk_pf_file_type FOREIGN KEY (product_file_type_id) REFERENCES product.product_file_type(id),
	CONSTRAINT fk_pf_product FOREIGN KEY (product_id) REFERENCES product.product(id) ON DELETE CASCADE,
	CONSTRAINT fk_product_file_src FOREIGN KEY (src_product_file_id) REFERENCES product.product_file(id),
	CONSTRAINT fk_product_file_status FOREIGN KEY (product_file_status_id) REFERENCES product.product_file_status(id)
);
CREATE INDEX idx_product_file_dl_url ON product.product_file USING btree (dl_url) INCLUDE (product_id) WHERE (dl_url IS NOT NULL);
CREATE INDEX idx_product_file_file_product ON product.product_file USING btree (file_id, product_id);
CREATE INDEX idx_product_file_product_file ON product.product_file USING btree (product_id, file_id);
CREATE INDEX idx_product_file_src ON product.product_file USING btree (src_product_file_id) WHERE (src_product_file_id IS NOT NULL);

The one with fk_pfft_product looks like this, it has about 5000 records in it:

CREATE TABLE product.product_file_tag (
	id uuid NOT NULL,
	c_tim timestamptz NOT NULL DEFAULT CURRENT_TIMESTAMP,
	c_uid uuid NULL,
	c_sid uuid NULL,
	m_tim timestamptz NOT NULL DEFAULT CURRENT_TIMESTAMP,
	m_uid uuid NULL,
	m_sid uuid NULL,
	product_file_id uuid NOT NULL,
	file_tag_id uuid NOT NULL,
	CONSTRAINT product_file_tag_pkey PRIMARY KEY (id),
	CONSTRAINT fk_pfft_file_tag FOREIGN KEY (file_tag_id) REFERENCES product.file_tag(id) ON DELETE CASCADE DEFERRABLE,
	CONSTRAINT fk_pfft_product FOREIGN KEY (product_file_id) REFERENCES product.product_file(id) ON DELETE CASCADE DEFERRABLE
);
CREATE UNIQUE INDEX uidx_product_file_file_tag ON product.product_file_tag USING btree (product_file_id, file_tag_id);

The other constraint has zero actual references, this returns zero:

select count(*) from product.product_file where src_product_file_id  in (
	select pf2_id from _td 
); -- 0 

I was trying to figure out how a foreign key constraint with zero actual references can cost 100 msec / record, but I failed.

Can somebody please explain what is wrong here?

The plan is also visualized here: http://tatiyants.com/pev/#/plans/plan_1692129126258

[
  {
    "Plan": {
      "Node Type": "ModifyTable",
      "Operation": "Delete",
      "Parallel Aware": false,
      "Async Capable": false,
      "Relation Name": "product_file",
      "Schema": "product",
      "Alias": "product_file",
      "Startup Cost": 4.21,
      "Total Cost": 840.79,
      "Plan Rows": 0,
      "Plan Width": 0,
      "Actual Startup Time": 0.567,
      "Actual Total Time": 0.568,
      "Actual Rows": 0,
      "Actual Loops": 1,
      "Shared Hit Blocks": 582,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 10,
      "Shared Written Blocks": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Temp Read Blocks": 0,
      "Temp Written Blocks": 0,
      "Plans": [
        {
          "Node Type": "Nested Loop",
          "Parent Relationship": "Outer",
          "Parallel Aware": false,
          "Async Capable": false,
          "Join Type": "Inner",
          "Startup Cost": 4.21,
          "Total Cost": 840.79,
          "Plan Rows": 100,
          "Plan Width": 46,
          "Actual Startup Time": 0.161,
          "Actual Total Time": 0.451,
          "Actual Rows": 90,
          "Actual Loops": 1,
          "Output": ["product_file.ctid", "\"ANY_subquery\".*"],
          "Inner Unique": true,
          "Shared Hit Blocks": 402,
          "Shared Read Blocks": 0,
          "Shared Dirtied Blocks": 10,
          "Shared Written Blocks": 0,
          "Local Hit Blocks": 0,
          "Local Read Blocks": 0,
          "Local Dirtied Blocks": 0,
          "Local Written Blocks": 0,
          "Temp Read Blocks": 0,
          "Temp Written Blocks": 0,
          "Plans": [
            {
              "Node Type": "Aggregate",
              "Strategy": "Hashed",
              "Partial Mode": "Simple",
              "Parent Relationship": "Outer",
              "Parallel Aware": false,
              "Async Capable": false,
              "Startup Cost": 3.79,
              "Total Cost": 4.79,
              "Plan Rows": 100,
              "Plan Width": 56,
              "Actual Startup Time": 0.118,
              "Actual Total Time": 0.136,
              "Actual Rows": 100,
              "Actual Loops": 1,
              "Output": ["\"ANY_subquery\".*", "\"ANY_subquery\".pf2_id"],
              "Group Key": ["\"ANY_subquery\".pf2_id"],
              "Planned Partitions": 0,
              "HashAgg Batches": 1,
              "Peak Memory Usage": 32,
              "Disk Usage": 0,
              "Shared Hit Blocks": 2,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 0,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0,
              "Plans": [
                {
                  "Node Type": "Subquery Scan",
                  "Parent Relationship": "Outer",
                  "Parallel Aware": false,
                  "Async Capable": false,
                  "Alias": "ANY_subquery",
                  "Startup Cost": 0.00,
                  "Total Cost": 3.54,
                  "Plan Rows": 100,
                  "Plan Width": 56,
                  "Actual Startup Time": 0.030,
                  "Actual Total Time": 0.083,
                  "Actual Rows": 100,
                  "Actual Loops": 1,
                  "Output": ["\"ANY_subquery\".*", "\"ANY_subquery\".pf2_id"],
                  "Shared Hit Blocks": 2,
                  "Shared Read Blocks": 0,
                  "Shared Dirtied Blocks": 0,
                  "Shared Written Blocks": 0,
                  "Local Hit Blocks": 0,
                  "Local Read Blocks": 0,
                  "Local Dirtied Blocks": 0,
                  "Local Written Blocks": 0,
                  "Temp Read Blocks": 0,
                  "Temp Written Blocks": 0,
                  "Plans": [
                    {
                      "Node Type": "Limit",
                      "Parent Relationship": "Subquery",
                      "Parallel Aware": false,
                      "Async Capable": false,
                      "Startup Cost": 0.00,
                      "Total Cost": 2.54,
                      "Plan Rows": 100,
                      "Plan Width": 16,
                      "Actual Startup Time": 0.024,
                      "Actual Total Time": 0.053,
                      "Actual Rows": 100,
                      "Actual Loops": 1,
                      "Output": ["_td.pf2_id"],
                      "Shared Hit Blocks": 2,
                      "Shared Read Blocks": 0,
                      "Shared Dirtied Blocks": 0,
                      "Shared Written Blocks": 0,
                      "Local Hit Blocks": 0,
                      "Local Read Blocks": 0,
                      "Local Dirtied Blocks": 0,
                      "Local Written Blocks": 0,
                      "Temp Read Blocks": 0,
                      "Temp Written Blocks": 0,
                      "Plans": [
                        {
                          "Node Type": "Seq Scan",
                          "Parent Relationship": "Outer",
                          "Parallel Aware": false,
                          "Async Capable": false,
                          "Relation Name": "_td",
                          "Schema": "public",
                          "Alias": "_td",
                          "Startup Cost": 0.00,
                          "Total Cost": 1100.07,
                          "Plan Rows": 43307,
                          "Plan Width": 16,
                          "Actual Startup Time": 0.023,
                          "Actual Total Time": 0.042,
                          "Actual Rows": 100,
                          "Actual Loops": 1,
                          "Output": ["_td.pf2_id"],
                          "Shared Hit Blocks": 2,
                          "Shared Read Blocks": 0,
                          "Shared Dirtied Blocks": 0,
                          "Shared Written Blocks": 0,
                          "Local Hit Blocks": 0,
                          "Local Read Blocks": 0,
                          "Local Dirtied Blocks": 0,
                          "Local Written Blocks": 0,
                          "Temp Read Blocks": 0,
                          "Temp Written Blocks": 0
                        }
                      ]
                    }
                  ]
                }
              ]
            },
            {
              "Node Type": "Index Scan",
              "Parent Relationship": "Inner",
              "Parallel Aware": false,
              "Async Capable": false,
              "Scan Direction": "Forward",
              "Index Name": "product_file_pkey",
              "Relation Name": "product_file",
              "Schema": "product",
              "Alias": "product_file",
              "Startup Cost": 0.42,
              "Total Cost": 8.36,
              "Plan Rows": 1,
              "Plan Width": 22,
              "Actual Startup Time": 0.003,
              "Actual Total Time": 0.003,
              "Actual Rows": 1,
              "Actual Loops": 100,
              "Output": ["product_file.ctid", "product_file.id"],
              "Index Cond": "(product_file.id = \"ANY_subquery\".pf2_id)",
              "Rows Removed by Index Recheck": 0,
              "Shared Hit Blocks": 400,
              "Shared Read Blocks": 0,
              "Shared Dirtied Blocks": 10,
              "Shared Written Blocks": 0,
              "Local Hit Blocks": 0,
              "Local Read Blocks": 0,
              "Local Dirtied Blocks": 0,
              "Local Written Blocks": 0,
              "Temp Read Blocks": 0,
              "Temp Written Blocks": 0
            }
          ]
        }
      ]
    },
    "Planning": {
      "Shared Hit Blocks": 0,
      "Shared Read Blocks": 0,
      "Shared Dirtied Blocks": 0,
      "Shared Written Blocks": 0,
      "Local Hit Blocks": 0,
      "Local Read Blocks": 0,
      "Local Dirtied Blocks": 0,
      "Local Written Blocks": 0,
      "Temp Read Blocks": 0,
      "Temp Written Blocks": 0
    },
    "Planning Time": 0.249,
    "Triggers": [
      {
        "Trigger Name": "RI_ConstraintTrigger_a_26535",
        "Constraint Name": "fk_pfft_product",
        "Relation": "product_file",
        "Time": 4.600,
        "Calls": 90
      },
      {
        "Trigger Name": "RI_ConstraintTrigger_a_26837",
        "Constraint Name": "fk_product_file_src",
        "Relation": "product_file",
        "Time": 5.795,
        "Calls": 90
      },
      {
        "Trigger Name": "RI_ConstraintTrigger_a_75463",
        "Constraint Name": "fk_pfq_src_product_file",
        "Relation": "product_file",
        "Time": 11179.429,
        "Calls": 90
      },
      {
        "Trigger Name": "_trg_002_aiu_audit_row",
        "Relation": "product_file",
        "Time": 49.410,
        "Calls": 90
      }
    ],
    "Execution Time": 11240.265
  }
]