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.

[TheCry]

Hello..
we currently have exactly the same problem:

-rw-rw---- 1 mysql mysql 11G Oct 31 08:33 history.ibd
-rw-rw---- 1 mysql mysql 12G Oct 31 08:33 sla_history_state.ibd
-rw-rw---- 1 mysql mysql 24G Oct 31 08:33 state_history.ibd

This is because we need every alarm (volatile = true) for the traps.
I would like to reduce the history to 30 days, but then the icingadb daemon crashes.
Is there a way to manually reduce the table to 30 days?
@epinter
would you share your script with us? I always get very nervous when it comes to the ICINGA database

[epinter]

Hello.. we currently have exactly the same problem:

-rw-rw---- 1 mysql mysql 11G Oct 31 08:33 history.ibd
-rw-rw---- 1 mysql mysql 12G Oct 31 08:33 sla_history_state.ibd
-rw-rw---- 1 mysql mysql 24G Oct 31 08:33 state_history.ibd

This is because we need every alarm (volatile = true) for the traps. I would like to reduce the history to 30 days, but then the icingadb daemon crashes. Is there a way to manually reduce the table to 30 days? @epinter would you share your script with us? I always get very nervous when it comes to the ICINGA database

This is a quick and dirty script to just run the delete commands. I started with "limit 1", I remember at some point I used limit 500, but the query must run quickly to not hold any other queries from icinga. IIRC I got these commands from mysql process list and changed the condition.

#!/usr/bin/perl
use DBI;
use strict;
use threads;
$|=1;

for(1..40) {
    threads->create(\&del);
}
my $t = threads->create(\&del);
$t->join();

sub del {
    my $dbh = DBI->connect("DBI:mysql:database=icingadb;host=localhost");
    while(1) {
        $dbh->do("delete from state_history where event_time < unix_timestamp(date_add(now(), interval -240 day))*1000 limit 1") || warn $@;
        $dbh->do("delete from sla_history_state where event_time < unix_timestamp(date_add(now(), interval -240 day))*1000 limit 1") || warn $@;
        print ".";
    }
    $dbh->disconnect;
}

You have to disable the retention or icinga will continue to try to run the slow query.