1

I'm using RDS Aurora with MySQL 5.6.

I have a delete query on a table which runs once in a day and it fails with lock wait time outexception, try restarting transaction.

This issue is not happening regularly, it happens very randomly which makes it difficult to analyze. I am not using any explicit transactions like using begin. AutoCommit is enabled and Transaction isolation level is default REPEATABLE READ). Multiple Inserts and Selects happen on this table very frequently. I understand that it waits for 50 Sec before giving up. I got the Innodb status and Process list. I saw some transactions are active for a long time like 17 Hours in some cases.Below status shows that some blocking transactions are waiting for 390 Seconds Enabled Performance Schema followed (https://www.psce.com/en/blog/2015/01/22/tracking-mysql-query-history-in-long-running-transactions/) Able to get multiple queries with the same thread id, probably they probably they might be using the same connection from the tomcat pool.

Table Schema

CREATE TABLE EVENT_DETAILS
(
  ORG_ID CHAR(32) NOT NULL,
  CONFIG_KEY CHAR(32) NOT NULL,
  COMPONENT_NAME VARCHAR(512) NOT NULL,
  REQUEST_ID  CHAR(32) NOT NULL,
  UPDATE_DATE INT NOT NULL,
  UPDATE_TIME INT NOT NULL,
  CLIENT CHAR(16) NOT NULL,
  STATUS INT NOT NULL,
  EVENT_DATA VARCHAR(1024),
  MESSAGE VARCHAR(512),
  INSERTED_TIME     TIMESTAMP      DEFAULT CURRENT_TIMESTAMP NOT NULL,
  INDEX STATE_INDEX  (UPDATE_DATE, UPDATE_TIME, ORG_ID, CONFIG_KEY, COMPONENT_NAME, STATUS, CLIENT)
);

Table has no primary Keys and Index is not Unique.

------------
TRANSACTIONS
------------
Trx id counter 39664912
Purge done for trx's n:o < 39661203 undo n:o < 0 state: running but idle
History list length 1207
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 39664853, not started
MySQL thread id 269, OS thread handle 0x2b90a2ee3700, query id 657304 10.103.88.40 administrator cleaned up
---TRANSACTION 39664826, not started
MySQL thread id 268, OS thread handle 0x2b90a2ea2700, query id 657292 10.103.88.40 administrator cleaned up
---TRANSACTION 39664892, not started
MySQL thread id 267, OS thread handle 0x2b90a2ea2700, query id 657343 10.103.88.40 administrator cleaned up
---TRANSACTION 39663626, not started
MySQL thread id 262, OS thread handle 0x2b90a2fe7700, query id 657356 10.103.88.40 administrator init
SHOW ENGINE INNODB STATUS
---TRANSACTION 39664820, not started
MySQL thread id 254, OS thread handle 0x2b90a2ea2700, query id 657289 10.103.88.40 administrator delayed commit ok done
---TRANSACTION 39663144, not started
MySQL thread id 247, OS thread handle 0x2b9070f88700, query id 656951 10.103.88.51 administrator cleaned up
---TRANSACTION 39661868, not started
MySQL thread id 234, OS thread handle 0x2b9070f88700, query id 654548 10.103.88.40 administrator cleaned up
---TRANSACTION 39664902, not started
MySQL thread id 194, OS thread handle 0x2b90d3a40700, query id 657346 10.103.88.51 administrator cleaned up
---TRANSACTION 39640759, not started
MySQL thread id 184, OS thread handle 0x2b9070fc9700, query id 629172 10.103.88.51 administrator delayed commit ok done
---TRANSACTION 39652587, not started
MySQL thread id 138, OS thread handle 0x2b90a2ee3700, query id 639886 10.103.88.51 administrator delayed commit ok done
---TRANSACTION 39664865, not started
MySQL thread id 128, OS thread handle 0x2b90a2ee3700, query id 657315 10.103.88.40 administrator cleaned up
---TRANSACTION 39663665, not started
MySQL thread id 62, OS thread handle 0x2b90a2fe7700, query id 656200 10.103.88.51 administrator cleaned up
---TRANSACTION 39664440, not started
MySQL thread id 93, OS thread handle 0x2b90a2fa6700, query id 656949 10.103.89.37 administrator cleaned up
---TRANSACTION 39659236, not started
MySQL thread id 63, OS thread handle 0x2b90a2ea2700, query id 652337 10.103.88.51 administrator cleaned up
---TRANSACTION 39663987, not started
MySQL thread id 39, OS thread handle 0x2b9070f88700, query id 656514 10.103.88.40 administrator cleaned up
---TRANSACTION 39662986, not started
MySQL thread id 21, OS thread handle 0x2b9068f86700, query id 655533 localhost rdsadmin delayed send ok done
---TRANSACTION 39664637, not started
MySQL thread id 1, OS thread handle 0x2b9068fc7700, query id 657349 localhost rdsadmin delayed send ok done
---TRANSACTION 39664682, not started
MySQL thread id 3, OS thread handle 0x2b9068fc7700, query id 657190 localhost rdsadmin cleaned up
---TRANSACTION 39664906, not started
MySQL thread id 2, OS thread handle 0x2b9070ec5700, query id 657355 localhost rdsadmin delayed send ok done
---TRANSACTION 39664531, ACTIVE 36 sec fetching rows
mysql tables in use 1, locked 1
LOCK WAIT 6139 lock struct(s), heap size 376, 116083 row lock(s)
MySQL thread id 275, OS thread handle 0x2b90a2e61700, query id 657035 10.103.89.37 administrator updating
DELETE from CONFIGSTOREQASTAGINGREL.EVENT_DETAILS where UPDATE_DATE < 20191015 AND COMPONENT_NAME = 'health'
------- TRX HAS BEEN WAITING 35 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 194 page no 10073 n bits 46 index `GEN_CLUST_INDEX` of table `CONFIGSTOREQASTAGINGREL`.`EVENT_DETAILS` trx id 39664531 lock_mode X waiting
Record lock, heap no 46 PHYSICAL RECORD: n_fields 14; compact format; info bits 0
 0: len=6; bufptr=0x2b90ac8ff23b; hex= 00000020fec2; asc       ;;
 1: len=6; bufptr=0x2b90ac8ff241; hex= 0000025d2e9d; asc    ]. ;;
 2: len=7; bufptr=0x2b90ac8ff247; hex= 9000001ad40110; asc        ;;
 3: len=30; bufptr=0x2b90ac8ff24e; hex= 653332333939633738383231626638616462323763653039383864393137; asc e32399c78821bf8adb27ce0988d917; (total 32 bytes);
 4: len=30; bufptr=0x2b90ac8ff26e; hex= 393962613134393834643637393236396639353936343538346632323630; asc 99ba14984d679269f95964584f2260; (total 32 bytes);
 5: len=30; bufptr=0x2b90ac8ff28e; hex= 706372732d484953544f524943414c2d506f77657243656e7465725f5265; asc pcrs-HISTORICAL-PowerCenter_Re; (total 38 bytes);
 6: len=30; bufptr=0x2b90ac8ff2b4; hex= 344b3433373444353468636947336c534464563371622020202020202020; asc 4K4374D54hciG3lSDdV3qb        ; (total 32 bytes);
 7: len=4; bufptr=0x2b90ac8ff2d4; hex= 81341728; asc  4 (;;
 8: len=4; bufptr=0x2b90ac8ff2d8; hex= 80000282; asc     ;;
 9: len=16; bufptr=0x2b90ac8ff2dc; hex= 646174612d636f6c6c6563746f722020; asc data-collector  ;;
 10: len=4; bufptr=0x2b90ac8ff2ec; hex= 80000001; asc     ;;
 11: len=30; bufptr=0x2b90ac8ff2f0; hex= 393962613134393834643637393236396639353936343538346632323630; asc 99ba14984d679269f95964584f2260; (total 245 bytes);
 12: len=30; bufptr=0x2b90ac8ff3e5; hex= 436f6c6c656374696f6e20636f6d706c6574656420737563636573736675; asc Collection completed successfu; (total 33 bytes);
 13: len=4; bufptr=0x2b90ac8ff406; hex= 5da6bbe9; asc ]   ;;

------------------
---TRANSACTION 39661213, ACTIVE 390 sec
4 lock struct(s), heap size 376, 6 row lock(s), undo log entries 34
MySQL thread id 245, OS thread handle 0x2b9070fc9700, query id 657295 10.103.88.40 administrator cleaned up
Trx read view will not see trx with id >= 39661214, sees < 39661213
--------





    mysql> show processlist;
+-----+---------------+--------------------+-------------------------+---------+------+------------------------+------------------------------------------------------------------------------------------------------+
| Id  | User          | Host               | db                      | Command | Time | State                  | Info                                                                                                 |
+-----+---------------+--------------------+-------------------------+---------+------+------------------------+------------------------------------------------------------------------------------------------------+
|   1 | rdsadmin      | localhost          | NULL                    | Sleep   |    1 | delayed send ok done   | NULL                                                                                                 |
|   2 | rdsadmin      | localhost          | NULL                    | Sleep   |    1 | delayed send ok done   | NULL                                                                                                 |
|   3 | rdsadmin      | localhost          | NULL                    | Sleep   |    4 | cleaned up             | NULL                                                                                                 |
|  21 | rdsadmin      | localhost          | NULL                    | Sleep   |  234 | delayed send ok done   | NULL                                                                                                 |
|  39 | administrator | 10.103.88.40:36280 | CONFIGSTOREQASTAGINGREL | Sleep   |  119 | cleaned up             | NULL                                                                                                 |
|  62 | administrator | 10.103.88.51:45652 | CONFIGSTOREQASTAGINGREL | Sleep   |    6 | cleaned up             | NULL                                                                                                 |
|  63 | administrator | 10.103.88.51:45654 | CONFIGSTOREQASTAGINGREL | Sleep   |  617 | cleaned up             | NULL                                                                                                 |
|  93 | administrator | 10.103.89.37:34512 | CONFIGSTOREQASTAGINGREL | Sleep   |   61 | cleaned up             | NULL                                                                                                 |
| 128 | administrator | 10.103.88.40:48708 | CONFIGSTOREQASTAGINGREL | Sleep   |    1 | cleaned up             | NULL                                                                                                 |
| 138 | administrator | 10.103.88.51:54406 | CONFIGSTOREQASTAGINGREL | Sleep   | 1413 | delayed commit ok done | NULL                                                                                                 |
| 184 | administrator | 10.103.88.51:60550 | CONFIGSTOREQASTAGINGREL | Sleep   | 2765 | delayed commit ok done | NULL                                                                                                 |
| 194 | administrator | 10.103.88.51:36468 | RCSQASTAGINGREL         | Sleep   |    1 | cleaned up             | NULL                                                                                                 |
| 234 | administrator | 10.103.88.40:39282 | CONFIGSTOREQASTAGINGREL | Sleep   |  335 | cleaned up             | NULL                                                                                                 |
| 245 | administrator | 10.103.88.40:34848 | CONFIGSTOREQASTAGINGREL | Sleep   |   19 | cleaned up             | NULL                                                                                                 |
| 247 | administrator | 10.103.88.51:46624 | CONFIGSTOREQASTAGINGREL | Sleep   |   60 | cleaned up             | NULL                                                                                                 |
| 254 | administrator | 10.103.88.40:41764 | CONFIGSTOREQASTAGINGREL | Sleep   |   19 | delayed commit ok done | NULL                                                                                                 |
| 261 | administrator | 10.103.88.40:45674 | NULL                    | Sleep   |  853 | cleaned up             | NULL                                                                                                 |
| 262 | administrator | 10.103.88.40:47332 | CONFIGSTOREQASTAGINGREL | Query   |    0 | init                   | show processlist                                                                                     |
| 263 | administrator | 10.103.89.26:47910 | CONFIGSTOREQASTAGINGREL | Sleep   |  535 | delayed send ok done   | NULL                                                                                                 |
| 267 | administrator | 10.103.88.40:49682 | CONFIGSTOREQASTAGINGREL | Sleep   |    7 | delayed commit ok done | NULL                                                                                                 |
| 268 | administrator | 10.103.88.40:49684 | CONFIGSTOREQASTAGINGREL | Sleep   |   19 | cleaned up             | NULL                                                                                                 |
| 269 | administrator | 10.103.88.40:49686 | CONFIGSTOREQASTAGINGREL | Sleep   |   18 | cleaned up             | NULL                                                                                                 |
| 275 | administrator | 10.103.89.37:47946 | CONFIGSTOREQASTAGINGREL | Query   |   46 | updating               | DELETE from CONFIGSTOREQASTAGINGREL.EVENT_DETAILS where UPDATE_DATE < 20191015 AND COMPONENT_NAME =  |
+-----+---------------+--------------------+-------------------------+---------+------+------------------------+------------------------------------------------------------------------------------------------------+
23 rows in set (0.00 sec)

My Intention was to identify the blocking transaction and not to kill the thread, so that i can fix my code instead of killing the blocking thread all the time.

mysql> SELECT r.trx_id waiting_trx_id,
    -> r.trx_mysql_thread_id waiting_thread,
    -> r.trx_query waiting_query,
    -> b.trx_id blocking_trx_id,
    -> b.trx_mysql_thread_id blocking_thread,
    -> b.trx_query blocking_query
    -> FROM information_schema.innodb_lock_waits w
    -> INNER JOIN information_schema.innodb_trx b ON
    -> b.trx_id = w.blocking_trx_id
    -> INNER JOIN information_schema.innodb_trx r ON
    -> r.trx_id = w.requesting_trx_id;
+----------------+----------------+--------------------------------------------------------------------------------------------------------------+-----------------+-----------------+----------------+
| waiting_trx_id | waiting_thread | waiting_query                                                                                                | blocking_trx_id | blocking_thread | blocking_query |
+----------------+----------------+--------------------------------------------------------------------------------------------------------------+-----------------+-----------------+----------------+
| 39664531       |            275 | DELETE from CONFIGSTOREQASTAGINGREL.EVENT_DETAILS where UPDATE_DATE < 20191015 AND COMPONENT_NAME = 'health' | 39661213        |             245 | NULL           |
+----------------+----------------+--------------------------------------------------------------------------------------------------------------+-----------------+-----------------+----------------+
1 row in set (0.00 sec)



mysql> select * from information_schema.innodb_trx where trx_id = 39661213;
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 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 |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 39661213 | RUNNING   | 2019-10-16 06:42:39 | NULL                  | NULL             |         38 |                 245 | NULL      | NULL                |                 0 |                 0 |                4 |                   376 |               6 |                34 |                       0 | REPEATABLE READ     |                 1 |                      1 | NULL                       |                         0 |                         0 |                0 |                          0 |
+----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
1 row in set (0.00 sec)

Also sometimes, I see transactions lying around like

---TRANSACTION 45639276, ACTIVE 69125 sec -- 19.201389 Hours
1 lock struct(s), heap size 376, 0 row lock(s), undo log entries 1969
MySQL thread id 14, OS thread handle 0x2b4c65948700, query id 947637 10.103.88.40 administrator delayed send ok done
Trx read view will not see trx with id >= 45639277, sees < 45638005
---TRANSACTION 45638005, ACTIVE 69297 sec -- 19.249167 Hours
2 lock struct(s), heap size 376, 1 row lock(s), undo log entries 1965
MySQL thread id 20, OS thread handle 0x2b4c64ac5700, query id 945359 10.103.88.40 administrator cleaned up
Trx read view will not see trx with id >= 45638026, sees < 45638005

Can someone tell what does undo log entries 1969 means for this transaction?? and In what scenarios these undo log entries grows ??

mysql> select * from information_schema.innodb_trx;
+-----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 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 |
+-----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
| 973262572 | RUNNING   | 2019-11-08 07:56:28 | NULL                  | NULL             |        255 |               32394 | NULL      | NULL                |                 0 |                 0 |                1 |                   376 |               0 |               254 |                       0 | REPEATABLE READ     |                 1 |                      1 | NULL                       |                         0 |                         0 |                0 |                          0 |
| 973256714 | RUNNING   | 2019-11-08 07:52:02 | NULL                  | NULL             |        152 |               32466 | NULL      | NULL                |                 0 |                 0 |                4 |                   376 |               2 |               148 |                       0 | REPEATABLE READ     |                 1 |                      1 | NULL                       |                         0 |                         0 |                0 |                          0 |
| 973246706 | RUNNING   | 2019-11-08 07:43:19 | NULL                  | NULL             |        423 |               41255 | NULL      | NULL                |                 0 |                 0 |                1 |                   376 |               0 |               422 |                       0 | REPEATABLE READ     |                 1 |                      1 | NULL                       |                         0 |                         0 |                0 |                          0 |
+-----------+-----------+---------------------+-----------------------+------------------+------------+---------------------+-----------+---------------------+-------------------+-------------------+------------------+-----------------------+-----------------+-------------------+-------------------------+---------------------+-------------------+------------------------+----------------------------+---------------------------+---------------------------+------------------+----------------------------+
3 rows in set (0.02 sec)

If you see here, these three transactions are active for last 3 hr (When I collected this Info) and Transaction 973256714 has row locks also, this is causing my delete to fail

Improve this question

1 Answer 1

Reset to default
2

No PRIMARY KEY == bad. (Not fatal, but bad.)

That DELETE can be sped up by having

INDEX(COMPONENT_NAME, UPDATE_DATE)

But what we really need to see is the other query that was running and blocking the DELETE. Look around for other queries, even SELECTs, that touch the table.

"Lock wait timeout" implies that one query is hanging onto that table for longer than lock_wait_timeout (which defaults to 50 seconds). And your DELETE would happily run once it let go. (A "Deadlock" is a more complex blockage, that cannot be resolved by waiting.)

How big is the table? How many rows are likely to be deleted each time?

DELETEing 50K rows at one time take a long time because of building the undo log entries. Instead of deleting a day's worth each day, delete an hour's worth each hour. Or adopt one of the suggestions here: http://mysql.rjweb.org/doc.php/deletebig

And make sure you have not left autocommit=OFF.

Improve this answer
16
  • Please find the details asked for , Table will be having around 300k Records on average, and Delete query will be deleting around 50k records once in a day. As you are pointing to check for selects (We don't use any Locking Reads , like select for Update and select in share mode is not used till now), Does a normal select query like (Select * from Table where Col = something) can lock the records in the table ??.Frequency of such selects are high on this table along with Inserts, We don't have Update usecase even on this table.
    – user3865748
    Commented Nov 8, 2019 at 5:13
  • I added another paragraph.
    – Rick James
    Commented Nov 8, 2019 at 21:32
  • Yes, I agree with your suggestions on Delete, But the problem here is delete is waiting for some other transactions to release the record lock. How can an implicit transaction (I mean transaction started by Mysql) doesn't get closed after insert's or select's ??.May I know in what scenarioes Mysql doesn't close the transaction ?? . Added a new block in the Question regarding the Active Transactions
    – user3865748
    Commented Nov 10, 2019 at 8:25
  • @user3865748 - The usual cause is autocommit=OFF, some SQL, then forget to COMMIT.
    – Rick James
    Commented Nov 10, 2019 at 15:18
  • In my case AutoCommit is enabled by default, still I'm to see long running transactions
    – user3865748
    Commented Nov 11, 2019 at 10:13

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.