When your query is blocked, but there is no blocking query - Part 3

In the previous blog posts I've talked about transactions which block other transactions but don't do anything and about some possible solutions.

In this post I will show you how to get even more information about what is locked by a transaction.

As you might have noticed the information_schema.innodb_locks table doesn't show all locks. This is what the documentation says:
"The INNODB_LOCKS table contains information about each lock that an InnoDB transaction has requested but not yet acquired, and each lock that a transaction holds that is blocking another transaction."

So if would like to know all locks held by a transaction this doesn't help.

There is lots of information in the output of "SHOW ENGINE INNODB STATUS\G" in the section about TRANSACTIONS.

------------
TRANSACTIONS
------------
Trx id counter 8991
Purge done for trx's n:o < 8991 undo n:o < 0 state: running but idle
History list length 50
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 3, OS thread handle 0x7ff0c8727700, query id 202 localhost msandbox init
show engine innodb status
---TRANSACTION 8972, ACTIVE 1313 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 2, OS thread handle 0x7ff0c8768700, query id 106 localhost msandbox update
insert into t1 values(4)
------- TRX HAS BEEN WAITING 1313 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 18 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`t1` trx id 8972 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

------------------
---TRANSACTION 8970, ACTIVE 1652 sec
4 lock struct(s), heap size 1184, 10 row lock(s), undo log entries 9
MySQL thread id 1, OS thread handle 0x7ff0c87a9700, query id 21 localhost msandbox cleaning up

So there are 10 row locks held by transaction 8970 and transaction 8972 is waiting on record lock on test.t1. That's nothing new, that information is also in INNODB_LOCKS and INNODB_LOCK_WAITS.

But if we set  innodb_status_output_locks to ON this changes.

mysql [information_schema] > set global innodb_status_output_locks=ON;
Query OK, 0 rows affected (0.00 sec)

mysql [information_schema] > show engine innodb status\G
...some output removed...
------------
TRANSACTIONS
------------
Trx id counter 8991
Purge done for trx's n:o < 8991 undo n:o < 0 state: running but idle
History list length 50
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 3, OS thread handle 0x7ff0c8727700, query id 204 localhost msandbox init
show engine innodb status
---TRANSACTION 8972, ACTIVE 1544 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s)
MySQL thread id 2, OS thread handle 0x7ff0c8768700, query id 106 localhost msandbox update
insert into t1 values(4)
------- TRX HAS BEEN WAITING 1544 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 18 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`t1` trx id 8972 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

------------------
TABLE LOCK table `test`.`t1` trx id 8972 lock mode IX
RECORD LOCKS space id 18 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`t1` trx id 8972 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

---TRANSACTION 8970, ACTIVE 1883 sec
4 lock struct(s), heap size 1184, 10 row lock(s), undo log entries 9
MySQL thread id 1, OS thread handle 0x7ff0c87a9700, query id 21 localhost msandbox cleaning up
TABLE LOCK table `test`.`t1` trx id 8970 lock mode IX
RECORD LOCKS space id 18 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`t1` trx id 8970 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000313; asc       ;;
 1: len 6; hex 000000001f4e; asc      N;;
 2: len 7; hex bd000001750110; asc     u  ;;
 3: len 4; hex 80000001; asc     ;;

Record lock, heap no 3 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000314; asc       ;;
 1: len 6; hex 000000001f4e; asc      N;;
 2: len 7; hex bd00000175011e; asc     u  ;;
 3: len 4; hex 80000002; asc     ;;

Record lock, heap no 4 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000315; asc       ;;
 1: len 6; hex 000000001f4e; asc      N;;
 2: len 7; hex bd00000175012c; asc     u ,;;
 3: len 4; hex 80000003; asc     ;;

Record lock, heap no 5 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000406; asc       ;;
 1: len 6; hex 000000002113; asc     ! ;;
 2: len 7; hex 92000001800110; asc        ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 6 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 00000000040c; asc       ;;
 1: len 6; hex 000000002116; asc     ! ;;
 2: len 7; hex 95000001590110; asc     Y  ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 7 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000412; asc       ;;
 1: len 6; hex 00000000211c; asc     ! ;;
 2: len 7; hex 990000015c0110; asc     \  ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 8 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000419; asc       ;;
 1: len 6; hex 00000000211e; asc     ! ;;
 2: len 7; hex 9b0000014d0110; asc     M  ;;
 3: len 4; hex 80000004; asc     ;;

Record lock, heap no 9 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000500; asc       ;;
 1: len 6; hex 00000000230a; asc     # ;;
 2: len 7; hex 8a0000013c0110; asc     <  ;;
 3: len 4; hex 80000004; asc     ;;

TABLE LOCK table `tmp`.`#sql2cfe_1_0` trx id 8970 lock mode IX
RECORD LOCKS space id 18 page no 3 n bits 80 index `GEN_CLUST_INDEX` of table `test`.`t1` trx id 8970 lock_mode X locks rec but not gap
Record lock, heap no 9 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 6; hex 000000000500; asc       ;;
 1: len 6; hex 00000000230a; asc     # ;;
 2: len 7; hex 8a0000013c0110; asc     <  ;;
 3: len 4; hex 80000004; asc     ;;
...some output removed...

Now we get to see the full information about the InnoDB locks.

There is one more thing in the SHOW ENGINE INNODB STATUS output you should pay attention to: deadlocks.

As you can see the record locks use the GEN_CLUST_INDEX index which is the index that is used if no primary key is specified. For some locking issues adding one or more indexes can fix the issue as InnoDB then doesn't need to take as many row locks.

When your query is blocked, but there is no blocking query - Part 2

In my previous post I talked about a transaction which blocked other transactions without doing anything. I talked about finding data from the blocking transaction using SYS and performance_schema.

But what are the possible solutions?

The first solution is to (automatically) kill the blocking transactions. Long running transactions can also stall the purging in InnoDB. See this blog post by Mark Leith about a possible solution.

The second solution would be make the application end the transaction sooner and/or to commit more often. Depending on your application this might or might not work. I consider this the best solution.

The third solution is to change the transaction isolation level of the blocking transaction to READ COMMITTED.

mysql [test] > set transaction isolation level read committed;
Query OK, 0 rows affected (0.00 sec)

mysql [test] > start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql [test] > insert into t2 select * from t1;
Query OK, 6 rows affected (0.00 sec)
Records: 6  Duplicates: 0  Warnings: 0

This works. The transaction won't need to lock as much as it did with REPEATABLE READ and the INSERT/DELETE on t1 from another transaction won't be blocked. Be careful to set the binlog_format to ROW before trying this as READ COMMITTED requires this to work.

mysql [test] > set session binlog_format=STATEMENT;
ERROR 1559 (HY000): Cannot switch out of the row-based binary log 
format when the session has open temporary tables
mysql [test] > drop table t2;
Query OK, 0 rows affected (0.01 sec)

mysql [test] > set session binlog_format=STATEMENT;
Query OK, 0 rows affected (0.00 sec)

mysql [test] > create temporary table t2 (id int);                              
Query OK, 0 rows affected (0.01 sec)

mysql [test] > set transaction isolation level read committed;                  
Query OK, 0 rows affected (0.00 sec)

mysql [test] > insert into t2 select * from t1;
ERROR 1665 (HY000): Cannot execute statement: impossible to write to 
binary log since BINLOG_FORMAT = STATEMENT and at least one table 
uses a storage engine limited to row-based logging. InnoDB is limited 
to row-logging when transaction isolation level is READ COMMITTED or 
READ UNCOMMITTED.

Setting the transaction isolation can also be done in my.cnf.

When your query is blocked, but there is no blocking query

When I queried information_schema.innodb_trx (introduced in 5.1 with the InnoDB Plugin) I noticed there were a few transactions in LOCK WAIT state.

Example:

mysql [information_schema] > select trx_id,trx_state 

    -> from information_schema.innodb_trx;
+--------+-----------+
| trx_id | trx_state |
+--------+-----------+
| 7974   | LOCK WAIT |
| 7962   | RUNNING   |
+--------+-----------+
2 rows in set (0.00 sec)

Then I made a query to join a few information_schema and performance_schema tables to find out which query was blocking my transactions. It turned out that the blocking transaction had a trx_query=NONE. So my query was block by a transaction doing nothing. That's not really helpful.

Let's try to recreate the situation and see exactly what happened. I'll use two sessions for the transactions and a third to monitor the server.

The first session:

mysql [test] > create table t1 (id int);
Query OK, 0 rows affected (0.01 sec)

mysql [test] > insert into t1 values(1),(2),(3);
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql [test] > create temporary table t2 (id int);
Query OK, 0 rows affected (0.01 sec)

mysql [test] > start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql [test] > insert into t2 select * from t1;
Query OK, 3 rows affected (0.00 sec)
Records: 3  Duplicates: 0  Warnings: 0

The second session:

mysql [test] > insert into t1 values(4);

Now the second session is waiting.

Let's start a third session to see what's happening. If the second session hits a wait timeout, you can just restart it.

mysql [information_schema] > select * from innodb_trx\G
*************************** 1. row ***************************
                    trx_id: 8022
                 trx_state: LOCK WAIT
               trx_started: 2014-10-25 11:38:25
     trx_requested_lock_id: 8022:18:3:1
          trx_wait_started: 2014-10-25 11:38:25
                trx_weight: 2
       trx_mysql_thread_id: 19
                 trx_query: insert into t1 values(4)
       trx_operation_state: inserting
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 360
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 10000
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
*************************** 2. row ***************************
                    trx_id: 8020
                 trx_state: RUNNING
               trx_started: 2014-10-25 11:35:07
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 6
       trx_mysql_thread_id: 1
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 0
          trx_lock_structs: 3
     trx_lock_memory_bytes: 360
           trx_rows_locked: 4
         trx_rows_modified: 3
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 10000
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
2 rows in set (0.00 sec)

mysql [information_schema] > select * from innodb_lock_waits\G
*************************** 1. row ***************************
requesting_trx_id: 8022
requested_lock_id: 8022:18:3:1
  blocking_trx_id: 8020
 blocking_lock_id: 8020:18:3:1
1 row in set (0.00 sec)

mysql [information_schema] > select * from innodb_locks\G
*************************** 1. row ***************************
    lock_id: 8022:18:3:1
lock_trx_id: 8022
  lock_mode: X
  lock_type: RECORD
 lock_table: `test`.`t1`
 lock_index: GEN_CLUST_INDEX
 lock_space: 18
  lock_page: 3
   lock_rec: 1
  lock_data: supremum pseudo-record
*************************** 2. row ***************************
    lock_id: 8020:18:3:1
lock_trx_id: 8020
  lock_mode: S
  lock_type: RECORD
 lock_table: `test`.`t1`
 lock_index: GEN_CLUST_INDEX
 lock_space: 18
  lock_page: 3
   lock_rec: 1
  lock_data: supremum pseudo-record
2 rows in set (0.00 sec)

mysql [information_schema] > use sys
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
mysql [sys] > select * from innodb_lock_waits\G
*************************** 1. row ***************************
     waiting_trx_id: 8022
     waiting_thread: 19
      waiting_query: insert into t1 values(4)
    waiting_lock_id: 8022:18:3:1
  waiting_lock_mode: X
  waiting_lock_type: RECORD
 waiting_lock_table: `test`.`t1`
 waiting_lock_index: GEN_CLUST_INDEX
    blocking_trx_id: 8020
    blocking_thread: 1
     blocking_query: NULL
   blocking_lock_id: 8020:18:3:1
 blocking_lock_mode: S
 blocking_lock_type: RECORD
blocking_lock_table: `test`.`t1`
blocking_lock_index: GEN_CLUST_INDEX
1 row in set (0.00 sec)

The last query is from the SYS schema. You'll need version 1.3.0 of SYS for this to work.

So we now know which transaction is blocking which transaction, but we don't yet know what that transaction is doing as blocking_query is NULL.

But we have blocking_thread=1. With performance_schema we can find the statements executed in that thread:

mysql [performance_schema] > SELECT SQL_TEXT FROM events_statements_history_long 

    -> WHERE thread_id=(SELECT thread_id FROM threads WHERE processlist_id=1) 

    -> order by TIMER_START;
+---------------------------------+
| SQL_TEXT                        |
+---------------------------------+
| rollback                        |
| start transaction               |
| insert into t2 select * from t1 |
+---------------------------------+
3 rows in set (0.00 sec)

You should be aware that there are 3 ID's with which we are dealing:

• The InnoDB Transaction ID (trx_id)
• The MySQL Processlist ID (information_schema.processlist.ID, used in blocking_thread)
• The MySQL Thread ID (performance_schema.threads.thread_id)

This can help you to identify what the application in the idle thread was doing and what might happen to it if you would just kill the query.

It might also be possible to find OS pid if the application uses a connector which supports connection attributes. The host on which this pid lives can be found in the processlist.

mysql [performance_schema] > select * from session_connect_attrs where PROCESSLIST_ID=2;
+----------------+-----------------+----------------+------------------+
| PROCESSLIST_ID | ATTR_NAME       | ATTR_VALUE     | ORDINAL_POSITION |
+----------------+-----------------+----------------+------------------+
|              2 | _os             | linux-glibc2.5 |                0 |
|              2 | _client_name    | libmysql       |                1 |
|              2 | _pid            | 25415          |                2 |
|              2 | _client_version | 5.6.21         |                3 |
|              2 | _platform       | x86_64         |                4 |
|              2 | program_name    | mysql          |                5 |
+----------------+-----------------+----------------+------------------+
6 rows in set (0.00 sec)

For this procedure to succeed you'll need this:

1. MySQL 5.6 or newer.
2. performance_schema must be enabled
3. In setup_consumers events_statements_history_long must be enabled.
4. The performance_schema_events_statements_history_long_size variable must be set large enough. Changing this requires a restart of the server. With this variable you specify how many statements there are kept in the events_statements_history_long table. You probably need to raise this on a busy server to get the statements of the blocking transaction as the transaction might be waiting for quite some time.

Disabling old_passwords=1

It is possible to disallow users from using old_passwords=1. This can be done by adding 'maximum-old_passwords=0' to your my.cnf

This prevents users from generating passwords hashes in pre-4.1 format. In MySQL 5.7 old_passwords=1 is already disabled, so this is only useful on 5.6 and earlier.

Be aware that this also restricts old_passwords=2 which is needed for sha256 hashes.

mysql> select @@old_passwords;
+-----------------+
| @@old_passwords |
+-----------------+
|               0 |
+-----------------+
1 row in set (0.00 sec)

mysql> set old_passwords=1;
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql> show warnings;
+---------+------+----------------------------------------------+
| Level   | Code | Message                                      |
+---------+------+----------------------------------------------+
| Warning | 1292 | Truncated incorrect old_passwords value: '1' |
+---------+------+----------------------------------------------+
1 row in set (0.00 sec)

mysql> select @@old_passwords;
+-----------------+
| @@old_passwords |
+-----------------+
|               0 |
+-----------------+
1 row in set (0.00 sec)