Interactive Debugging of Transaction Conflicts with TokuDB

Interactive Debugging of Transaction Conflicts with TokuDB

I am developing a concurrent application that uses TokuDB to store its database. Sometimes, one of my SQL statements returns with a 'lock wait timeout exceeded' error. How do I identify the cause of this error?

TokuDB 7.1 provides access to the set of locks taken and the set of locks that are blocked via tables in the MYSQL information schema. In addition, TokuDB stores the last lock conflict information in a session variable that can be retrieved by the application.

Transactions and Locks

Example

Suppose that I create a table with a single column that is the primary key.

mysql> show create table t;
Create Table: CREATE TABLE `t` (
  `id` int(11) NOT NULL,
  PRIMARY KEY (`id`)
) ENGINE=TokuDB DEFAULT CHARSET=latin1

Suppose that I have 2 MySQL clients with ID's 1 and 2 respectively. Suppose that MySQL client 1 inserts some values into the table 't'. TokuDB transaction 51 is created for the insert statement. Since autocommit is off, transaction 51 is still live after the insert statement completes, and I can query the 'tokudb_locks' information schema table to see the locks that are held by the transaction.

mysql 1> set autocommit=off;

mysql 1> insert into t values (1),(10),(100);
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql 1> select * from information_schema.tokudb_locks;
+--------------+-----------------------+---------------+----------------+-----------------+
| locks_trx_id | locks_mysql_thread_id | locks_dname   | locks_key_left | locks_key_right |
+--------------+-----------------------+---------------+----------------+-----------------+
|           51 |                     1 | ./test/t-main | 0001000000     | 0001000000      |
|           51 |                     1 | ./test/t-main | 000a000000     | 000a000000      |
|           51 |                     1 | ./test/t-main | 0064000000     | 0064000000      |
+--------------+-----------------------+---------------+----------------+-----------------+

mysql 1> select * from information_schema.tokudb_lock_waits;
Empty set (0.00 sec)

The keys are currently hex dumped. Someday we will pretty print the keys.

Now we switch to the other MySQL client with ID 2.

mysql 2> insert into t values (2),(20),(100);
The insert gets blocked since there is a conflict on the primary key with value 100.

The granted TokuDB locks are:

mysql 1> select * from information_schema.tokudb_locks;
+--------------+-----------------------+---------------+----------------+-----------------+
| locks_trx_id | locks_mysql_thread_id | locks_dname   | locks_key_left | locks_key_right |
+--------------+-----------------------+---------------+----------------+-----------------+
|           51 |                     1 | ./test/t-main | 0001000000     | 0001000000      |
|           51 |                     1 | ./test/t-main | 000a000000     | 000a000000      |
|           51 |                     1 | ./test/t-main | 0064000000     | 0064000000      |
|           62 |                     2 | ./test/t-main | 0002000000     | 0002000000      |
|           62 |                     2 | ./test/t-main | 0014000000     | 0014000000      |
+--------------+-----------------------+---------------+----------------+-----------------+

The locks that are pending due to a conflict are:

mysql 1> select * from information_schema.tokudb_lock_waits;
+-------------------+-----------------+------------------+---------------------+----------------------+-----------------------+
| requesting_trx_id | blocking_trx_id | lock_waits_dname | lock_waits_key_left | lock_waits_key_right | lock_waits_start_time |
+-------------------+-----------------+------------------+---------------------+----------------------+-----------------------+
|                62 |              51 | ./test/t-main    | 0064000000          | 0064000000           |         1380656990910 |
+-------------------+-----------------+------------------+---------------------+----------------------+-----------------------+

Eventually, the lock for client 2 times out, and we can retrieve a JSON document that describes the conflict.

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

mysql 2> select @@tokudb_last_lock_timeout;
+----------------------------------------------------------------------------------------------------------------+
| @@tokudb_last_lock_timeout                                                                                     |
+----------------------------------------------------------------------------------------------------------------+
| {"mysql_thread_id":2, "dbname":"./test/t-main", "requesting_txnid":62, "blocking_txnid":51, "key":"0064000000"} |
+----------------------------------------------------------------------------------------------------------------+

mysql 2> rollback;

Since transaction 62 was rolled back, all of the locks taken by it are released.

mysql 1> select * from information_schema.tokudb_locks;
+--------------+-----------------------+---------------+----------------+-----------------+
| locks_trx_id | locks_mysql_thread_id | locks_dname   | locks_key_left | locks_key_right |
+--------------+-----------------------+---------------+----------------+-----------------+
|           51 |                     1 | ./test/t-main | 0001000000     | 0001000000      |
|           51 |                     1 | ./test/t-main | 000a000000     | 000a000000      |
|           51 |                     1 | ./test/t-main | 0064000000     | 0064000000      |
+--------------+-----------------------+---------------+----------------+-----------------+