Mysql long-term cleanup transaction

Question

I am trying to debug the "Wait wait wait wait" error in MySQL (AWS RDS) v5.6.19a, which occasionally occurs when I try to select a row using the primary identifier for the update, that is:

SELECT primary_id FROM tbl_widgets WHERE primary_id = 5 FOR UPDATE 

After debugging for many hours, I ruled out that another part of my application "directly" blocked the same line (which was the obvious culprit). Thus, I began to delve into the rabbit hole, which is mysql blocking, and noticed the following correlation between the crossed out error "Waiting timeout timeout" and the information provided:

 SHOW ENGINE INNODB STATUS; 

In a purge state that blocks a slowly increasing number of rows for ~ 10 minutes, there is a long TRANSACTION transaction, here are the corresponding rows for this transaction of 10 manual INNODB STATUS requests:

 2015-08-19 13:29:04 ---TRANSACTION 25861246681, ACTIVE 158 sec 10 lock struct(s), heap size 1184, 21 row lock(s), undo log entries 20 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7146839061 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:29:42 ---TRANSACTION 25861246681, ACTIVE 196 sec 13 lock struct(s), heap size 2936, 28 row lock(s), undo log entries 27 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147149416 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:30:10 ---TRANSACTION 25861246681, ACTIVE 224 sec 13 lock struct(s), heap size 2936, 31 row lock(s), undo log entries 30 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147321023 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:30:41 ---TRANSACTION 25861246681, ACTIVE 255 sec 13 lock struct(s), heap size 2936, 35 row lock(s), undo log entries 34 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147511090 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:31:12 ---TRANSACTION 25861246681, ACTIVE 286 sec 15 lock struct(s), heap size 2936, 38 row lock(s), undo log entries 37 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147604774 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:31:30 ---TRANSACTION 25861246681, ACTIVE 304 sec 21 lock struct(s), heap size 2936, 42 row lock(s), undo log entries 39 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147789789 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:31:57 ---TRANSACTION 25861246681, ACTIVE 331 sec 21 lock struct(s), heap size 2936, 46 row lock(s), undo log entries 43 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147837536 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:32:28 ---TRANSACTION 25861246681, ACTIVE 362 sec 22 lock struct(s), heap size 2936, 51 row lock(s), undo log entries 48 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7147905807 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:33:16 ---TRANSACTION 25861246681, ACTIVE 410 sec 23 lock struct(s), heap size 2936, 58 row lock(s), undo log entries 55 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7148317478 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 2015-08-19 13:33:49 ---TRANSACTION 25861246681, ACTIVE 443 sec 24 lock struct(s), heap size 2936, 64 row lock(s), undo log entries 61 MySQL thread id 5110120, OS thread handle 0x2ba082506700, query id 7148471519 10.0.1.154 mfuser cleaning up Trx read view will not see trx with id >= 25861246682, sees < 25861246682 

I stumbled upon the following blog post ( http://databaseblog.myname.nl/2014/10/when-your-query-is-blocked-but-there-is_26.html ) which provides a potential solution that helps determine what happens in this long-term transaction, in particular the set:

 set GLOBAL innodb_status_output_locks=ON; 

Unfortunately, this operation cannot be performed in RDS due to limited permissions.

I would like to request some debugging help on how I can decide what happens in this cleanup transaction, and possibly how to avoid all of this.

Edit to add: Average CPU usage by MySQL instance is 20%

Answer 1

In my case, my “cleansing” locks went away after I killed the JVM. I ran my debugger. Apparently, they were the remnants of an earlier debugging run, which I interrupted before the transaction was cleared.

This probably won't help you, but here are a couple of suggestions for debugging in this situation.

• You have one piece of information, which is the number of locks. Using breakpoints, you can pause the application in different places to try to pinpoint when the counter is incrementing. (Or maybe it rises only after certain errors are detected in the log or only after certain user actions.)

• If you cannot use breakpoints, you have another tool, which is the select for update statement, which locks after locking. You might be able to sprinkle it around your code, perhaps with additional logging to determine where the lock starts.

• Consider temporarily debugging an application from a locally installed MySQL database. This can be installed either on the local server or on your development machine. This can be a setup problem, but it can have many other benefits (for example, a test bed for db scripts, the ability to work on a laptop offline.)

All of this assumes that the lock is caused by your own code, and not by some other task. (The cleansing user "mfuser" is in your log.) This allows you to reproduce the problem on demand.