Debugging InnoDB Locks using the new InnoDB Plugin’s Information Schema Tables

Tracking down InnoDB lock information using the new Information Schema tables provided with the InnoDB plugin has never been easier.

Long story short, the other day I was trying to identify what transaction was holding the lock for a particular UPDATE. The UPDATE would not complete and kept timing out with “Lock wait timeout exceeded; try restarting transaction”.

Of course I checked the output of SHOW ENGINE INNODB STATUS. From that output, I could tell it was the replication thread holding the lock, *since* it was the only other transaction running. But I could not verify this with output, it just had to be the case.

Next I enabled the InnoDB lock monitor, and examined that output too. Here, it showed more detail on the locks being held, however, it only shows the first 10 locks held by the replication thread. In this case, the replication thread was holding more than 2000 record locks from a large, open transaction. Needless to say, the lock I was looking for was not amongst the 10 displayed.

So I enabled InnoDB plugin (just added the following 2 lines to my config file and restarted mysqld):

ignore_builtin_innodb
plugin-load=innodb=ha_innodb_plugin.dll;innodb_trx=ha_innodb_plugin.dll;
innodb_locks=ha_innodb_plugin.dll;innodb_lock_waits=ha_innodb_plugin.dll;
innodb_cmp=ha_innodb_plugin.dll;innodb_cmp_reset=ha_innodb_plugin.dll;
innodb_cmpmem=ha_innodb_plugin.dll;innodb_cmpmem_reset=ha_innodb_plugin.dll

After the above, you’ll notice the following new tables in Information Schema:

mysql> SHOW TABLES IN INFORMATION_SCHEMA LIKE 'INNODB_%';
+-----------------------------------------+
| Tables_in_information_schema (INNODB_%) |
+-----------------------------------------+
| INNODB_CMP_RESET                        |
| INNODB_TRX                              |
| INNODB_CMPMEM_RESET                     |
| INNODB_LOCK_WAITS                       |
| INNODB_CMPMEM                           |
| INNODB_CMP                              |
| INNODB_LOCKS                            |
+-----------------------------------------+
7 rows in set (0.00 sec)

For this particular problem, I wanted to see what was in INNODB_TRX, INNODB_LOCKS, and INNODB_LOCK_WAITS:

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 |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
| 124616 | LOCK WAIT | 2010-06-23 13:51:52 | 124616:1301:1572:6 | 2010-06-23 13:51:52 | 2 | 496854 | NULL |
| 123900 | RUNNING | 2010-06-23 09:30:59 | NULL | NULL | 506 | 3 | NULL |
+--------+-----------+---------------------+-----------------------+---------------------+------------+---------------------+-----------+
2 rows in set (0.00 sec)

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_LOCKS;
+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+
| lock_id | lock_trx_id | lock_mode | lock_type | lock_table | lock_index | lock_space | lock_page | lock_rec | lock_data |
+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+
| 124616:1301:1572:6 | 124616 | X | RECORD | `db1`.`t1` | `PRIMARY` | 1301 | 1572 | 6 | 4100 |
| 123900:1301:1572:6 | 123900 | S | RECORD | `db1`.`t1` | `PRIMARY` | 1301 | 1572 | 6 | 4100 |
+--------------------+-------------+-----------+-----------+-------------------------+------------+------------+-----------+----------+-----------+
2 rows in set (0.01 sec)

mysql> SELECT * FROM INFORMATION_SCHEMA.INNODB_LOCK_WAITS;
+-------------------+--------------------+-----------------+--------------------+
| requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id |
+-------------------+--------------------+-----------------+--------------------+
| 124616 | 124616:1301:1572:6 | 123900 | 123900:1301:1572:6 |
+-------------------+--------------------+-----------------+--------------------+
1 row in set (0.00 sec)

Finally, I had conclusive evidence that it was indeed the replication thread (trx id 123900) holding the lock which was blocking the UPDATE.

I also found the exact row which was being held, and all of the details, such as it was a S (shared) record lock, and the the lock was on the primary key of table db1.t1. It even tells you the lock_space (1301), the lock_page (1572), the lock_rec (6) , and the actual data, lock_data (4100).

The other key piece was the time (or trx_started) for the running transaction, 123900. With that, we knew exactly where to check the binlogs for the exact statement where this all began.

In conclusion, I wish I had started here to begin with, so keep this in mind for the future. And this is just one example of how beneficial these new InnoDB Plugin Information Schema tables can be for troubleshooting. You can find even more details/examples at the following location:

http://dev.mysql.com/doc/innodb-plugin/1.0/en/innodb-information-schema-examples.html


Click here to give this article a “Thumbs Up” on Planet MySQL !

  

Tags: , , , , , , , , ,

2 Responses to “Debugging InnoDB Locks using the new InnoDB Plugin’s Information Schema Tables”

  1. [...] Chris on MySQL Tips and Solutions for MySQL, MySQL Proxy, and other MySQL-related Topics « Debugging InnoDB Locks using the new InnoDB Plugin’s Information Schema Tables [...]


Period Panties by Period Panteez Menstrual Underwear Menstruation PMS Panty