The error we are seeing in the logs is:
1465547 [pool-2-thread-1] WARN o.h.e.jdbc.spi.SqlExceptionHelper - SQL Error: 1205, SQLState: 41000
1465547 [pool-2-thread-1] ERROR o.h.e.jdbc.spi.SqlExceptionHelper - Lock wait timeout exceeded; try restarting transaction
1465549 [pool-2-thread-1] ERROR c.a.s.DefaultScheduledTaskRunner - failed to execute scheduled task 'event-processing
javax.persistence.LockTimeoutException: could not execute statement
Caused by: org.hibernate.exception.LockTimeoutException: could not execute statement
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
APS is enacting a series of parallel processes for the management, tracking, and delivery of assets from the ACS application. During this there are several periods where the content is handed off to another service for activities to take place, and then because of the asynchronous nature of that service, the process polls for completion.
The processes to date have been written such that the polling took place as a service task, with the status handling as an exclusive gateway in the process definition, to determine if the other service has completed its activities, with a loop.
Due to an outage, the remote service failed, and the loop continued running for several thousand processes over a weekend.
The result that we have identified is that the ACT_EVT_LOG table now contains 43 million rows, and the APS services attempting to work with it are grinding to a halt.
This was initially identified as two servers in a deadlock battle over which could get the lock over process events, but even after resolving this by taking all servers out of action apart from one we’re still seeing that the attempt to get lock over process events is timing out.
Is there is a way to remove unnecessary entries from the ACT_EVT_LOG table so that the activities using it take less time, and the system can attempt to resume functionality?
There are other things we need to do as a result of this; changing the polling task which waits from being a set of workflow events to being a piece of code seems initially to be a good way to prevent this, but are there others we should be careful of and look to ensure we don’t make mistakes that will cripple performance like this in the future.
Results of a couple of queries are:
mysql> show full processlist;
+-----+----------+---------------------+---------+---------+------+----------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+----------+---------------------+---------+---------+------+----------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | rdsadmin | localhost | NULL | Sleep | 0 | delayed send ok done | NULL |
| 2 | rdsadmin | localhost | NULL | Sleep | 0 | cleaned up | NULL |
| 3 | rdsadmin | localhost | NULL | Sleep | 4 | cleaned up | NULL |
| 4 | rdsadmin | localhost | NULL | Sleep | 9 | delayed send ok done | NULL |
| 985 | activiti | 10.160.35.138:34026 | process | Sleep | 2 | delayed send ok done | NULL |
| 988 | activiti | 10.160.35.138:34153 | process | Sleep | 371 | delayed send ok done | NULL |
| 989 | activiti | 10.160.35.138:34156 | process | Sleep | 371 | delayed send ok done | NULL |
| 990 | activiti | 10.160.35.138:34157 | process | Query | 334 | updating | update ACT_EVT_LOG set LOCK_OWNER_='5035a137-1388-4db5-ac3c-594d12b4fe0f_expired', LOCK_TIME_='2020-08-11 14:00:00.007' where IS_PROCESSED_=0 and (LOCK_TIME_ is not null) and LOCK_TIME_<'2020-08-11 13:50:00.007' |
| 991 | activiti | 10.160.35.138:34197 | process | Sleep | 371 | delayed send ok done | NULL |
| 992 | activiti | 10.160.35.138:34205 | process | Sleep | 371 | delayed send ok done | NULL |
| 993 | activiti | 10.160.35.138:34234 | process | Sleep | 371 | delayed send ok done | NULL |
| 994 | activiti | 10.160.35.138:34233 | process | Sleep | 345 | delayed send ok done | NULL |
| 995 | activiti | 10.160.35.138:34257 | process | Sleep | 2 | delayed send ok done | NULL |
| 996 | activiti | 10.160.35.138:34258 | process | Query | 8 | updating | update ACT_EVT_LOG set LOCK_OWNER_='5035a137-1388-4db5-ac3c-594d12b4fe0f', LOCK_TIME_='2020-08-11 14:05:26.529' where LOG_NR_>=3996255 and LOG_NR_<3996355 and IS_PROCESSED_=0 and (LOCK_OWNER_ is null) and (LOCK_TIME_ is null) |
| 997 | activiti | 10.160.35.138:34279 | NULL | Query | 0 | init | show full processlist |
+-----+----------+---------------------+---------+---------+------+----------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
15 rows in set (0.00 sec)
mysql> SELECT * FROM `information_schema`.`innodb_trx` ORDER BY `trx_started`;
+-----------+-----------+---------------------+-------------------------+---------------------+------------+---------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| trx_id | trx_state | trx_started | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | trx_query | trx_operation_state | trx_tables_in_use | trx_tables_locked | trx_lock_structs | trx_lock_memory_bytes | trx_rows_locked | trx_rows_modified | trx_concurrency_tickets | trx_isolation_level | trx_unique_checks | trx_foreign_key_checks | trx_last_foreign_key_error | trx_adaptive_hash_latched | trx_adaptive_hash_timeout | trx_is_read_only | trx_autocommit_non_locking |
+-----------+-----------+---------------------+-------------------------+---------------------+------------+---------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 427836316 | RUNNING | 2020-08-11 14:00:00 | NULL | NULL | 5354375 | 990 | update ACT_EVT_LOG set LOCK_OWNER_='5035a137-1388-4db5-ac3c-594d12b4fe0f_expired', LOCK_TIME_='2020-08-11 14:00:00.007' where IS_PROCESSED_=0 and (LOCK_TIME_ is not null) and LOCK_TIME_<'2020-08-11 13:50:00.007' | fetching rows | 1 | 1 | 1367422 | 376 | 35135454 | 3986953 | 0 | REPEATABLE READ | 1 | 1 | NULL | 0 | 0 | 0 | 0 |
| 427838524 | LOCK WAIT | 2020-08-11 14:06:31 | 427838524:706:204356:22 | 2020-08-11 14:06:31 | 2 | 985 | update ACT_EVT_LOG set LOCK_OWNER_='5035a137-1388-4db5-ac3c-594d12b4fe0f', LOCK_TIME_='2020-08-11 14:06:31.099' where LOG_NR_>=3996255 and LOG_NR_<3996355 and IS_PROCESSED_=0 and (LOCK_OWNER_ is null) and (LOCK_TIME_ is null) | starting index read | 1 | 1 | 2 | 376 | 1 | 0 | 0 | REPEATABLE READ | 1 | 1 | NULL | 0 | 0 | 0 | 0 |
+-----------+-----------+---------------------+-------------------------+---------------------+------------+---------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
2 rows in set (0.03 sec)
