zabbix on postgresql - very slow delete of events

Hi

This will be a rather lengthy post, just to give the full (I hope) picture. We're using Zabbix for monitoring and I'm having problems

understanding why the deletion of rows in the events table is so slow.

Zabbix: 4.2 (never mind the name of the db - it is 4.2)

new values per second: ~400

hosts: ~600

items: ~45000

OS: CentOS Linux release 7.6.1810 (Core)

Postgresql was installed from the yum repo on postgresql.org

zabbix_34=> select version();

                                                 version

---------------------------------------------------------------------------------------------------------

PostgreSQL 10.8 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-36), 64-bit

(1 row)

The database is analyzed + vacuumed nightly. The server runs Zabbix and the database, has 16 GB memory, 4 vCPUs (modern hardware).

Some parameters:

shared_buffers = 3GB

work_mem = 10MB    (I also tested with work_mem = 128MB - no difference)       

effective_cache_size = 6 GB

effective_io_concurrency = 40

checkpoint_timeout = 5 min (default)

max_wal_size = 1 GB (default)

checkpoint_completion_target = 0.8

pg_wal is already on a separate device.

events table: ~25 million rows / 2.9 GB

event_recovery table: ~12 million rows / 550 MB

alerts table: ~600000 rows / 530 MB

Generally the database is quite snappy and shows no indication of problems. But now I've seen that housekeeping of events is

very slow - a single (normally hourly) run can take more than one day to finish, so events keep stacking up in the table. A typical slow

delete statement, from the postgres log:

postgresql-10-20190717-031404.log:2019-07-17 03:37:43 CEST [80965]: [4-1] user=zabbix,db=zabbix_34,app=[unknown],client=[local]: LOG: duration: 27298798.930 ms statement: delete from events where (eventid between 5580621 and 5580681 or eventid between 5580689 and 5580762 or eventid between 5580769 and 5580844 or eventid between 5580851 and 5580867 or eventid between 5580869 and 5580926 or eventid between 5580933 and 5580949 or eventid between 5580963 and 5581024

--- 8< --- a lot of similar eventids snipped away -----

or eventid between 5586799 and 5586839 or eventid in (5581385,5581389,5581561,5581563,5581564,5581580,5 581582,5581584,5581585,5581635))

I've analyzed the deletion of a single row in events. First, some table information:

zabbix_34=> \d events

                                 Table "zabbix.events"

    Column    |          Type           | Collation | Nullable |        Default

--------------+-------------------------+-----------+----------+-----------------------

eventid      | numeric                 |           | not null |

source       | bigint                  |           | not null | '0'::bigint

object       | bigint                  |           | not null | '0'::bigint

objectid     | numeric                 |           | not null | '0'::numeric

clock        | bigint                  |           | not null | '0'::bigint

value        | bigint                  |           | not null | '0'::bigint

acknowledged | bigint                  |           | not null | '0'::bigint

ns           | bigint                  |           | not null | '0'::bigint

name         | character varying(2048) |           | not null | ''::character varying

severity     | integer                 |           | not null | 0

Indexes:

    "idx_29337_primary" PRIMARY KEY, btree (eventid)

    "events_1" btree (source, object, objectid, clock)

    "events_2" btree (source, object, clock)

    "events_clk_3" btree (clock)

Referenced by:

    TABLE "acknowledges" CONSTRAINT "c_acknowledges_2" FOREIGN KEY (eventid) REFERENCES events(eventid) ON UPDATE RESTRICT ON DELETE CASCADE

    TABLE "alerts" CONSTRAINT "c_alerts_2" FOREIGN KEY (eventid) REFERENCES events(eventid) ON UPDATE RESTRICT ON DELETE CASCADE

    TABLE "alerts" CONSTRAINT "c_alerts_5" FOREIGN KEY (p_eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "event_recovery" CONSTRAINT "c_event_recovery_1" FOREIGN KEY (eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "event_recovery" CONSTRAINT "c_event_recovery_2" FOREIGN KEY (r_eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "event_recovery" CONSTRAINT "c_event_recovery_3" FOREIGN KEY (c_eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "event_suppress" CONSTRAINT "c_event_suppress_1" FOREIGN KEY (eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "event_tag" CONSTRAINT "c_event_tag_1" FOREIGN KEY (eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "problem" CONSTRAINT "c_problem_1" FOREIGN KEY (eventid) REFERENCES events(eventid) ON DELETE CASCADE

    TABLE "problem" CONSTRAINT "c_problem_2" FOREIGN KEY (r_eventid) REFERENCES events(eventid) ON DELETE CASCADE

zabbix_34=> \d event_recovery

              Table "zabbix.event_recovery"

    Column     |  Type  | Collation | Nullable | Default

---------------+--------+-----------+----------+---------

eventid       | bigint |           | not null |

r_eventid     | bigint |           | not null |

c_eventid     | bigint |           |          |

correlationid | bigint |           |          |

userid        | bigint |           |          |

Indexes:

    "event_recovery_pkey" PRIMARY KEY, btree (eventid)

    "event_recovery_1" btree (r_eventid)

    "event_recovery_2" btree (c_eventid)

Foreign-key constraints:

    "c_event_recovery_1" FOREIGN KEY (eventid) REFERENCES events(eventid) ON DELETE CASCADE

    "c_event_recovery_2" FOREIGN KEY (r_eventid) REFERENCES events(eventid) ON DELETE CASCADE

    "c_event_recovery_3" FOREIGN KEY (c_eventid) REFERENCES events(eventid) ON DELETE CASCADE

zabbix_34=> \d alerts

                                 Table "zabbix.alerts"

    Column     |          Type           | Collation | Nullable |        Default

---------------+-------------------------+-----------+----------+-----------------------

alertid       | numeric                 |           | not null |

actionid      | numeric                 |           | not null |

eventid       | numeric                 |           | not null |

userid        | numeric                 |           |          |

clock         | bigint                  |           | not null | '0'::bigint

mediatypeid   | numeric                 |           |          |

sendto        | character varying(1024) |           | not null | ''::character varying

subject       | character varying(255)  |           | not null | ''::character varying

message       | text                    |           | not null | ''::text

status        | bigint                  |           | not null | '0'::bigint

retries       | bigint                  |           | not null | '0'::bigint

error         | character varying(2048) |           | not null | ''::character varying

esc_step      | bigint                  |           | not null | '0'::bigint

alerttype     | bigint                  |           | not null | '0'::bigint

p_eventid     | bigint                  |           |          |

acknowledgeid | bigint                  |           |          |

Indexes:

    "idx_29120_primary" PRIMARY KEY, btree (alertid)

    "alerts_1" btree (actionid)

    "alerts_2" btree (clock)

    "alerts_3" btree (eventid)

    "alerts_4" btree (status)

    "alerts_5" btree (mediatypeid)

    "alerts_6" btree (userid)

    "alerts_7" btree (p_eventid)

Foreign-key constraints:

    "c_alerts_1" FOREIGN KEY (actionid) REFERENCES actions(actionid) ON UPDATE RESTRICT ON DELETE CASCADE

    "c_alerts_2" FOREIGN KEY (eventid) REFERENCES events(eventid) ON UPDATE RESTRICT ON DELETE CASCADE

    "c_alerts_3" FOREIGN KEY (userid) REFERENCES users(userid) ON UPDATE RESTRICT ON DELETE CASCADE

    "c_alerts_4" FOREIGN KEY (mediatypeid) REFERENCES media_type(mediatypeid) ON UPDATE RESTRICT ON DELETE CASCADE

    "c_alerts_5" FOREIGN KEY (p_eventid) REFERENCES events(eventid) ON DELETE CASCADE

    "c_alerts_6" FOREIGN KEY (acknowledgeid) REFERENCES acknowledges(acknowledgeid) ON DELETE CASCADE

Let's look at what's in the tables for event 7123123:

zabbix_34=> select * from events where eventid=7123123;

eventid | source | object | objectid |   clock    | value | acknowledged |   ns    |                 name                 | severity

---------+--------+--------+----------+------------+-------+--------------+---------+--------------------------------------+----------

7123123 |      3 |      0 |    27562 | 1525264196 |     1 |            0 | 1980875 | Cannot calculate trigger expression. |        0

(1 row)

zabbix_34=> select * from event_recovery where eventid=7123123;

eventid | r_eventid | c_eventid | correlationid | userid

---------+-----------+-----------+---------------+--------

7123123 |   7124371 |           |               |

(1 row)

zabbix_34=> select * from alerts where eventid=7123123;

alertid | actionid | eventid | userid | clock | mediatypeid | sendto | subject | message | status | retries | error | esc_step | aler

ttype | p_eventid | acknowledgeid

---------+----------+---------+--------+-------+-------------+--------+---------+---------+--------+---------+-------+----------+-----

------+-----------+---------------

(0 rows)

All these queries execute well below 1 ms, using indexes.

Let's delete one row. See explain results here: https://explain.depesz.com/s/aycf . 5 seconds to delete a single row, wow!

This shows that it is the foreign key constraints on event_recovery and alerts that take a lot of time.

But why? I far as I can see, the delete is fully CPU bound during execution.

Deleting the corresponding row directly from event_recovery or alerts executes in less than 0.1 ms.  

Any ideas?

I've observed that alerts and event_recovery tables both have more than one foreign key that references events, if that matters.

Regards

Kristian Ejvind