Interactive Debugging of Transaction Conflicts with TokuDB

Posted On October 16, 2013 | By Rich Prohaska | 4 comments

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? First, I need to understand a little bit about how TokuDB transactions use locks. Then, I need to understand how to use the MySQL information schema to look at the current state of the locks.

Transactions and Locks

TokuDB uses key range locks to implement serializable transactions. These locks are acquired as the transaction progresses. The locks are released when the transaction commits or aborts.

TokuDB stores these locks in a data structure called the lock tree. The lock tree stores the set of range locks granted to each transaction. In addition, the lock tree stores the set of locks that are not granted due to a conflict with locks granted to some other transaction.

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.

Example

Here is an example debug session.

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;

I have 2 MySQL clients with ID’s 1 and 2 respectively. 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 coded document that describes the conflict.

mysql 2 insert continued>
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"} |
+-------------------------------------------------------------------------------------------------------------+

The JSON document encodes the database, table and index where the conflict occurred in the ‘dname’ key. The ‘key’ encodes the conflicting key. The ‘blocking_txnid’ encodes the transaction identifier that is blocking my transaction. I can find the MySQL client that created the blocking transaction via joins of information schema tables.

mysql> select * from information_schema.tokudb_trx,information_schema.processlist
where trx_id = 51 and trx_mysql_thread_id = id;
+--------+---------------------+----+----------+-----------+------+---------+------+-------+------+
| trx_id | trx_mysql_thread_id | ID | USER     | HOST      | DB   | COMMAND | TIME | STATE | INFO |
+--------+---------------------+----+----------+-----------+------+---------+------+-------+------+
| 51     | 1                   | 1  | prohaska | localhost | test | Sleep   | 151  |       | NULL |
+--------+---------------------+----+----------+-----------+------+---------+------+-------+------+

Now I have information about the two client operations that are conflicting and can hopefully change my application to avoid this conflict.

4 thoughts

  1. yam says:

    Hi

    I am using mysql-5.5.30-tokudb-7.0.4

    I found some insert queries are slow in slow query log.
    It seems that unique key has locked until finish insert transaction in tables include unique key.
    I think, because of unique key lock, other insert queries are not finish.

    Is it the feature of tokudb engine? or some bug?

    Here is my test to find this problem.

    Thank you.

    (tested in mysql-5.5.30-tokudb-7.0.4-linux-x86_64 and mysql-5.5.30-tokudb-7.1.0-linux-x86_64)

    ==============================================================================

    ## 1. Session 1 – table create
    mysql> create table uniqueTest (id int, unique key(id));

    ## 2. Session 1 – insert transaction start
    mysql> set session autocommit=off;
    mysql> begin;
    mysql> insert into uniqueTest values (1);

    ## 3. Session 2 – insert other row
    mysql> set session autocommit=on;
    mysql> insert into uniqueTest values (12345);
    ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
    mysql> select @@tokudb_last_lock_timeout;
    *************************** 1. row ***************************
    @@tokudb_last_lock_timeout: {“mysql_thread_id”:4, “dbname”:”./test/uniqueTest-key-id”, “requesting_txnid”:41469663, “blocking_txnid”:41469660, “key_left”:”ff0139300000″, “key_right”:”+infinity”}
    1 row in set (0.00 sec)

    ERROR:
    No query specified

  2. Rich Prohaska says:

    Hello,
    IMO, this is a bug.

    When inserting into the table, TokuDB uses a range lock (id >= 1) for session 1 to implement the uniqueness property on the id index. This is correct but causes serialization of other sessions since their range locks will conflict. A lock on the range (id == 1) for session 1 is also correct and allows concurrent insertions into the table since the range locks are unlikely to conflict. I will create an issue in our github repository for this problem.

  3. Rich Prohaska says:

    I created github issue https://github.com/Tokutek/ft-engine/issues/133 for this problem.

  4. yam says:

    Thank you. ^^

Leave a Reply

Your email address will not be published. Required fields are marked *