Lock wait timeout exceeded for state_history when using retention

[oxzi]

While working on another issue with a larger test instance, I ran into a database locking issue after enabling the Icinga DB retention.

After adding the following retention block to my config, the problems started.

retention:
  history-days: 1
  sla-days: 1

Shortly after restarting Icinga DB, the following error appeared, always for the state_history table.

2025-02-25T10:58:39.859Z        FATAL   icingadb        Error 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
can't perform "INSERT INTO \"state_history\" (\"previous_soft_state\", \"check_attempt\", \"check_source\", \"scheduling_source\", \"environment_id\", \"state_type\", \"id\", \"previous_hard_state\", \"output\", \"max_check_attempts\", \"object_type\", \"event_time\", \"endpoint_id\", \"soft_state\", \"long_output\", \"host_id\", \"service_id\", \"hard_state\") VALUES (:previous_soft_state,:check_attempt,:check_source,:scheduling_source,:environment_id,:state_type,:id,:previous_hard_state,:output,:max_check_attempts,:object_type,:event_time,:endpoint_id,:soft_state,:long_output,:host_id,:service_id,:hard_state) ON DUPLICATE KEY UPDATE \"id\" = VALUES(\"id\")"
github.com/icinga/icinga-go-library/database.CantPerformQuery
        github.com/icinga/icinga-go-library@v0.4.0/database/utils.go:16
github.com/icinga/icinga-go-library/database.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2.1
        github.com/icinga/icinga-go-library@v0.4.0/database/db.go:535
github.com/icinga/icinga-go-library/retry.WithBackoff
        github.com/icinga/icinga-go-library@v0.4.0/retry/retry.go:65
github.com/icinga/icinga-go-library/database.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2
        github.com/icinga/icinga-go-library@v0.4.0/database/db.go:530
golang.org/x/sync/errgroup.(*Group).Go.func1
        golang.org/x/sync@v0.10.0/errgroup/errgroup.go:78
runtime.goexit
        runtime/asm_amd64.s:1700
retry deadline exceeded
github.com/icinga/icinga-go-library/retry.WithBackoff
        github.com/icinga/icinga-go-library@v0.4.0/retry/retry.go:100
github.com/icinga/icinga-go-library/database.(*DB).NamedBulkExec.func1.(*DB).NamedBulkExec.func1.1.2
        github.com/icinga/icinga-go-library@v0.4.0/database/db.go:530
golang.org/x/sync/errgroup.(*Group).Go.func1
        golang.org/x/sync@v0.10.0/errgroup/errgroup.go:78
runtime.goexit
        runtime/asm_amd64.s:1700

Looking at the database process list, a parallel DELETE statement is executed for this table, looking like one generated by Icinga DB's retention part.

MariaDB [icingadb]> show processlist;
+-----+----------+-----------------+----------+---------+------+----------+---------------------------------------------------------------------------------------
---------------+----------+
| Id  | User     | Host            | db       | Command | Time | State    | Info
               | Progress |
+-----+----------+-----------------+----------+---------+------+----------+---------------------------------------------------------------------------------------
---------------+----------+
|  55 | icingadb | localhost:54518 | icingadb | Execute | 3341 | Updating | DELETE FROM state_history WHERE environment_id = ? AND event_time < ?
ORDER BY event_time LIMIT 5000 |    0.000 |
| 144 | icingadb | localhost       | icingadb | Query   |    0 | starting | show processlist
               |    0.000 |
+-----+----------+-----------------+----------+---------+------+----------+---------------------------------------------------------------------------------------
---------------+----------+
2 rows in set (0.000 sec)

Such a crash happened reproducibly; sometimes after five minutes, sometimes after an hour, but eventually it crashed. After disabling the retention part, it worked again.

[epinter]

I also have this crash, icingadb from both my master servers keeps crashing. My state_history table has 2.2 million records, the "limit 5000" is too high. I had disable the retention and write a script to run multiple threads with delete (limit 1) records in a loop, after the cleanup I will try to enable retention again.

[oxzi]

Thanks for confirming this issue, @epinter. I have just created #961 which lowers the cost of the retention queries. As an additional knob, the retention.count variable could be decreased.

For reference, I have calculated the query costs via PostgreSQL's execution planner as documented in the linked PR.

	LIMIT 5000	LIMIT 1000
ORDERED	0.41..662.54	0.41..132.84
w/ #961	0.00..264.82	0.00..52.96

[epinter]

Simply removing the order by and decreasing the limit to 1000 was not sufficient for me. The whole icinga was unusable while cleaning the db. While creating a script to remove the data (few millions of records), I tested with 500 and 1000. Things started to work when I left the loop with limit 10 or 1.

[oxzi]

@epinter: Thanks again for your feedback. Since you had some real life experience with this issue, please feel free to share both your mentioned deletion script and your experience with us. I would really appreciate it.

While reflecting on this issue, I had some random thoughts I wanted to write down.

There are eight RetentionStatements at the moment, launched concurrently in Retention.Start. If the state_history table is huge, the other tables may also be huge - resulting in lots of load on eight of the sixteen (default value) database connections.

However, after taking a step back, how does one end up with this issue? When migrating a huge history from the IDO, icingadb-migrate already allows limiting the time range. When configuring a retention from the start, this should not happen. Thus, it only occurs if one configures a retention later to shrink the database.

The current retention code works under the assumption that the queries shouldn't be too expensive, which is false when dealing with millions of entries. Reducing the LIMIT to 10 or 1 would result in a very long running deletion loop, being somewhat ineffective. But since there are no relationships/foreign key constraints, a big DELETE should be fast, especially when not performing an ORDER.

[oxzi]

I have just merged #961, reducing the query cost by dropping ORDER BY as shown in the EXPLAIN output in the PR. However, on huge setups as described by @epinter this may not be enough.

We could reduce the load by reducing the LIMIT as described above and introducing a cool down period since otherwise the queries would be executed in a loop without delay. However, this would slow down things by a lot.

As an alternative, we could consider this an "out of the usual" thing and move this to the docs, describing how to cleanup the database manually while having Icinga DB stopped.

I am open for feedback and other or even better suggestions.