Interactive Debugging of Transaction Conflicts with TokuDB

Interactive Debugging of Transaction Conflicts with TokuDB

Lets suppose that 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?

Example

Suppose that we 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 we 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 we 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      |
+--------------+-----------------------+---------------+----------------+-----------------+