MySQL idle connections still holding locks

We had an interesting problem today. We were seeing very slow single-row updates (>30s) on our (innodb) scheduled_jobs table, and a large number of the update queries were failing with a LOCK WAIT TIMEOUT. The updates were using the primary key, so they should be pretty fast - but they weren't.

So we fired up a console and ran SHOW INNODB STATUS, and saw lots of transactions with long-held locks -

---TRANSACTION 0 200086649, ACTIVE 3000 sec, process no 29791, OS thread id 140353331377936
12 lock struct(s), heap size 3024, 6 row lock(s), undo log entries 10
MySQL thread id 243, query id 314676 ip-10-94-245-79.ec2.internal 10.94.245.79 tn


- however, when we cross-referenced the MySQL thread IDs with a SHOW PROCESSLIST, we found that lots of the threads weren't actually doing anything:

+------+------------+-----------+-----------------+----------------+------+--------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+------+------------+-----------+-----------------+----------------+------+--------------+------------------+
| 243 | tn | (..snip..)| tn_production | Sleep | 3000 | | NULL


This was strange - but after a bit of a Googling and a few minutes thought, we realised the cause.

When one of our worker processes dies - e.g. either because monit has killed it for taking up too much resource for too long, or because the EC2 instance it's running on has become unresponsive to ssh and been automatically restarted by our detect-and-rescue script - it may be in the middle of a transaction at the point it's killed.

If the transaction was holding locks, and never got to the "COMMIT" stage, and the connection wasn't closed normally, then that connection will persist - and maintain its locks - until it gets timed-out by the MySQL server.... and the default wait_timeout variable is 28800s - 8 hrs!.

So, we killed the idle connections, and the update queries started going through much more quickly again. We've now brought our wait_timeout variable down to 10 mins, and we'll see how we get on.

This should not be possible - transactional fail?

We're having a bizarre problem with MySQL 5.0.32 on Debian in a highly-concurrent environment, using the ActiveRecord JDBC adapter. We've also seen it on 5.0.51 on Ubuntu.

There's a particular sequence of 3 queries, all executed from within a ActiveRecord::Base.transaction { } block:


// Statement 1:
INSERT INTO (InnoDB table 1)
(type, ...loads of other fields...)
SELECT 'ProtoMessageItem', ...other fields...
FROM (MyISAM table 1) LEFT OUTER JOIN (InnoDB table 2)
WHERE (anti-duplication clause)
GROUP BY (synthetic identifier on MyISAM table 1, to be a unique key on InnoDB table 1)

// Statement 2:
INSERT INTO (InnoDB table 2)
SELECT (fields)
FROM (MyISAM table 1) LEFT OUTER JOIN (InnoDB table 3) INNER JOIN (InnoDB table 1)
WHERE (anti-duplication clause)

// Statement 3:
UPDATE (InnoDB table 1)
SET type = 'MessageItem'
WHERE type = 'ProtoMessageItem'


Now, all of this takes place within an explicit transaction, and works well - this approach provides huge performance gains over the more simple and obvious methods.

The problem is that just very very occasionally, it breaks. We don't know how or why, but once in a blue moon, statement 2 throws a DUPLICATE KEY exception, and the transaction DOESN'T get rolled back. Statement 1 still gets COMMITTED. We can see ProtoMessageItems in the DB, and this blocks up the pipeline and stops further MessageItems from being created.

ProtoMessageItems should NEVER be visible - they're only ever created and then updated to full MessageItems in the same 3-statement transaction. Seeing them from outside that transaction is like seeing a naked singularity - it just shouldn't be possible.

This is all kinds of wrong in a very wrong way, as it means one of the following - either:

1. The DB is getting the correct BEGIN/COMMIT/ROLLBACK statements, but transactional atomicity is not holding for some reason


2. The JDBC driver is not sending the correct ROLLBACK statements, but thinks it's in autocommit mode


3. There's an obscure concurrency edge case somewhere with the ActiveRecord JDBC adapter, that means once in a while, for some reason, it starts that transaction in autocommit mode.

All of these possibilities are worrying. We've eliminated the possibility of it being some quirk of the particular data that causes this problem. We've turned on MySQL statement logging and watched it for hours, and as far as we can see, the correct ROLLBACK statements seem to be issued every time.

Has anyone encountered a similar problem? Any known issues with INSERT/SELECT on combinations of (transactional) InnoDB and (non-transactional) MyISAM tables?