Description:
sys.innodb_lock_waits showing the wrong blocking query.
/*** @SLAVE ***/
root@localhost [REPLI]> start transaction;select * from T_Sample01 where ID = 23 for update;
/*** @Master ***/
root@localhost [REPLI]> update T_Sample01 set memo = 'LOCK TEST FOR MEM5' where ID = 23;
/*** @SALVE ***/
root@localhost [REPLI]> show processlist; show engine innodb status\G show slave status\G select * from sys.innodb_lock_waits\G
+----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+
| 1 | system user | | NULL | Connect | 2030 | Waiting for master to send event | NULL |
| 2 | system user | | NULL | Connect | 12 | System lock | update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23 |
| 3 | event_scheduler | localhost | NULL | Daemon | 2030 | Waiting on empty queue | NULL |
| 6 | root | localhost | REPLI | Query | 0 | starting | show processlist |
+----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+
4 rows in set (0.00 sec)
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2018-03-23 21:44:25 0x7f7b14040700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 6 seconds
<SNIP>
------------
TRANSACTIONS
------------
Trx id counter 835758
Purge done for trx's n:o < 835745 undo n:o < 0 state: running but idle
History list length 0
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421641847433952, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 835757, ACTIVE 12 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 2, OS thread handle 140166124865280, query id 60074 System lock
update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23
------- TRX HAS BEEN WAITING 12 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 46 page no 3 n bits 96 index PRIMARY of table `REPLI`.`T_Sample01` trx id 835757 lock_mode X locks rec but not gap waiting
Record lock, heap no 28 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
0: len 4; hex 80000017; asc ;;
1: len 6; hex 00000009aedb; asc ;;
2: len 7; hex 25000000472f00; asc % G/ ;;
3: len 18; hex 4c4f434b205445535420464f52204d454d33; asc LOCK TEST FOR MEM3;;
------------------
---TRANSACTION 835756, ACTIVE 17 sec
2 lock struct(s), heap size 1136, 1 row lock(s)
MySQL thread id 6, OS thread handle 140166593513216, query id 60091 localhost root starting
show engine innodb status
Trx read view will not see trx with id >= 835758, sees < 835757
<SNIP>
----------------------------
END OF INNODB MONITOR OUTPUT
============================
1 row in set (0.00 sec)
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 192.168.56.113
<SNIP>
Slave_SQL_Running_State: System lock
Master_Retry_Count: 86400
<SNIP>
Replicate_Rewrite_DB:
Channel_Name:
Master_TLS_Version:
1 row in set (0.00 sec)
*************************** 1. row ***************************
wait_started: 2018-03-23 21:44:13
wait_age: 00:00:12
wait_age_secs: 12
locked_table: `REPLI`.`T_Sample01`
locked_index: PRIMARY
locked_type: RECORD
waiting_trx_id: 835757
waiting_trx_started: 2018-03-23 21:44:13
waiting_trx_age: 00:00:12
waiting_trx_rows_locked: 1
waiting_trx_rows_modified: 0
waiting_pid: 2
waiting_query: update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23
waiting_lock_id: 835757:46:3:28
waiting_lock_mode: X
blocking_trx_id: 835756
blocking_pid: 6
blocking_query: select * from sys.innodb_lock_waits <---This is wrong information..
blocking_lock_id: 835756:46:3:28
blocking_lock_mode: X
blocking_trx_started: 2018-03-23 21:44:08
blocking_trx_age: 00:00:17
blocking_trx_rows_locked: 1
blocking_trx_rows_modified: 0
sql_kill_blocking_query: KILL QUERY 6
sql_kill_blocking_connection: KILL 6
1 row in set, 3 warnings (0.01 sec)
/*** @SALVE ***/
root@localhost [REPLI]> select * from performance_schema.threads where processlist_state='System lock'\G
*************************** 1. row ***************************
THREAD_ID: 75
NAME: thread/sql/slave_sql
TYPE: FOREGROUND
PROCESSLIST_ID: 2
PROCESSLIST_USER: NULL
PROCESSLIST_HOST: NULL
PROCESSLIST_DB: NULL
PROCESSLIST_COMMAND: Connect
PROCESSLIST_TIME: 72
PROCESSLIST_STATE: System lock
PROCESSLIST_INFO: update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23
PARENT_THREAD_ID: 1
ROLE: NULL
INSTRUMENTED: YES
HISTORY: YES
CONNECTION_TYPE: NULL
THREAD_OS_ID: 3267
1 row in set (0.00 sec)
/*** @SALVE ***/
root@localhost [REPLI]> select * from INFORMATION_SCHEMA.INNODB_LOCK_WAITS\G
*************************** 1. row ***************************
requesting_trx_id: 835761
requested_lock_id: 835761:46:3:28
blocking_trx_id: 835756
blocking_lock_id: 835756:46:3:28
1 row in set, 1 warning (0.00 sec)
root@localhost [REPLI]> select * from INFORMATION_SCHEMA.INNODB_LOCKS\G
*************************** 1. row ***************************
lock_id: 835764:46:3:28
lock_trx_id: 835764
lock_mode: X
lock_type: RECORD
lock_table: `REPLI`.`T_Sample01`
lock_index: PRIMARY
lock_space: 46
lock_page: 3
lock_rec: 28
lock_data: 23
*************************** 2. row ***************************
lock_id: 835756:46:3:28
lock_trx_id: 835756
lock_mode: X
lock_type: RECORD
lock_table: `REPLI`.`T_Sample01`
lock_index: PRIMARY
lock_space: 46
lock_page: 3
lock_rec: 28
lock_data: 23
2 rows in set, 1 warning (0.00 sec)
How to repeat:
1) Start Transaction and Lock Row on the Slave
2) delete the specific row on the Master. (The row is locked on the slave)
3) system lock is occurred on the slave.
4) Run select * from sys.innodb_lock_waits, it shows wrong blocking query.
Suggested fix:
Please show correct blocking query on sys.innodb_lock_waits.
Description: sys.innodb_lock_waits showing the wrong blocking query. /*** @SLAVE ***/ root@localhost [REPLI]> start transaction;select * from T_Sample01 where ID = 23 for update; /*** @Master ***/ root@localhost [REPLI]> update T_Sample01 set memo = 'LOCK TEST FOR MEM5' where ID = 23; /*** @SALVE ***/ root@localhost [REPLI]> show processlist; show engine innodb status\G show slave status\G select * from sys.innodb_lock_waits\G +----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+ | Id | User | Host | db | Command | Time | State | Info | +----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+ | 1 | system user | | NULL | Connect | 2030 | Waiting for master to send event | NULL | | 2 | system user | | NULL | Connect | 12 | System lock | update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23 | | 3 | event_scheduler | localhost | NULL | Daemon | 2030 | Waiting on empty queue | NULL | | 6 | root | localhost | REPLI | Query | 0 | starting | show processlist | +----+-----------------+-----------+-------+---------+------+----------------------------------+-----------------------------------------------------------------+ 4 rows in set (0.00 sec) *************************** 1. row *************************** Type: InnoDB Name: Status: ===================================== 2018-03-23 21:44:25 0x7f7b14040700 INNODB MONITOR OUTPUT ===================================== Per second averages calculated from the last 6 seconds <SNIP> ------------ TRANSACTIONS ------------ Trx id counter 835758 Purge done for trx's n:o < 835745 undo n:o < 0 state: running but idle History list length 0 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 421641847433952, not started 0 lock struct(s), heap size 1136, 0 row lock(s) ---TRANSACTION 835757, ACTIVE 12 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 2, OS thread handle 140166124865280, query id 60074 System lock update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23 ------- TRX HAS BEEN WAITING 12 SEC FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 46 page no 3 n bits 96 index PRIMARY of table `REPLI`.`T_Sample01` trx id 835757 lock_mode X locks rec but not gap waiting Record lock, heap no 28 PHYSICAL RECORD: n_fields 4; compact format; info bits 0 0: len 4; hex 80000017; asc ;; 1: len 6; hex 00000009aedb; asc ;; 2: len 7; hex 25000000472f00; asc % G/ ;; 3: len 18; hex 4c4f434b205445535420464f52204d454d33; asc LOCK TEST FOR MEM3;; ------------------ ---TRANSACTION 835756, ACTIVE 17 sec 2 lock struct(s), heap size 1136, 1 row lock(s) MySQL thread id 6, OS thread handle 140166593513216, query id 60091 localhost root starting show engine innodb status Trx read view will not see trx with id >= 835758, sees < 835757 <SNIP> ---------------------------- END OF INNODB MONITOR OUTPUT ============================ 1 row in set (0.00 sec) *************************** 1. row *************************** Slave_IO_State: Waiting for master to send event Master_Host: 192.168.56.113 <SNIP> Slave_SQL_Running_State: System lock Master_Retry_Count: 86400 <SNIP> Replicate_Rewrite_DB: Channel_Name: Master_TLS_Version: 1 row in set (0.00 sec) *************************** 1. row *************************** wait_started: 2018-03-23 21:44:13 wait_age: 00:00:12 wait_age_secs: 12 locked_table: `REPLI`.`T_Sample01` locked_index: PRIMARY locked_type: RECORD waiting_trx_id: 835757 waiting_trx_started: 2018-03-23 21:44:13 waiting_trx_age: 00:00:12 waiting_trx_rows_locked: 1 waiting_trx_rows_modified: 0 waiting_pid: 2 waiting_query: update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23 waiting_lock_id: 835757:46:3:28 waiting_lock_mode: X blocking_trx_id: 835756 blocking_pid: 6 blocking_query: select * from sys.innodb_lock_waits <---This is wrong information.. blocking_lock_id: 835756:46:3:28 blocking_lock_mode: X blocking_trx_started: 2018-03-23 21:44:08 blocking_trx_age: 00:00:17 blocking_trx_rows_locked: 1 blocking_trx_rows_modified: 0 sql_kill_blocking_query: KILL QUERY 6 sql_kill_blocking_connection: KILL 6 1 row in set, 3 warnings (0.01 sec) /*** @SALVE ***/ root@localhost [REPLI]> select * from performance_schema.threads where processlist_state='System lock'\G *************************** 1. row *************************** THREAD_ID: 75 NAME: thread/sql/slave_sql TYPE: FOREGROUND PROCESSLIST_ID: 2 PROCESSLIST_USER: NULL PROCESSLIST_HOST: NULL PROCESSLIST_DB: NULL PROCESSLIST_COMMAND: Connect PROCESSLIST_TIME: 72 PROCESSLIST_STATE: System lock PROCESSLIST_INFO: update T_Sample01 set memo = 'LOCK TEST FOR MEM4' where ID = 23 PARENT_THREAD_ID: 1 ROLE: NULL INSTRUMENTED: YES HISTORY: YES CONNECTION_TYPE: NULL THREAD_OS_ID: 3267 1 row in set (0.00 sec) /*** @SALVE ***/ root@localhost [REPLI]> select * from INFORMATION_SCHEMA.INNODB_LOCK_WAITS\G *************************** 1. row *************************** requesting_trx_id: 835761 requested_lock_id: 835761:46:3:28 blocking_trx_id: 835756 blocking_lock_id: 835756:46:3:28 1 row in set, 1 warning (0.00 sec) root@localhost [REPLI]> select * from INFORMATION_SCHEMA.INNODB_LOCKS\G *************************** 1. row *************************** lock_id: 835764:46:3:28 lock_trx_id: 835764 lock_mode: X lock_type: RECORD lock_table: `REPLI`.`T_Sample01` lock_index: PRIMARY lock_space: 46 lock_page: 3 lock_rec: 28 lock_data: 23 *************************** 2. row *************************** lock_id: 835756:46:3:28 lock_trx_id: 835756 lock_mode: X lock_type: RECORD lock_table: `REPLI`.`T_Sample01` lock_index: PRIMARY lock_space: 46 lock_page: 3 lock_rec: 28 lock_data: 23 2 rows in set, 1 warning (0.00 sec) How to repeat: 1) Start Transaction and Lock Row on the Slave 2) delete the specific row on the Master. (The row is locked on the slave) 3) system lock is occurred on the slave. 4) Run select * from sys.innodb_lock_waits, it shows wrong blocking query. Suggested fix: Please show correct blocking query on sys.innodb_lock_waits.