| Bug #104245 | Wrong row lock number in SEIS | ||
|---|---|---|---|
| Submitted: | 7 Jul 2021 22:38 | Modified: | 9 Jul 2021 11:34 |
| Reporter: | Juan Arruti | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S3 (Non-critical) |
| Version: | 5.7.34 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[9 Jul 2021 11:34]
MySQL Verification Team
Hello Juan Arruti, Thank you for the report and test case. regards, Umesh
[9 Jul 2021 11:35]
MySQL Verification Team
MySQL Server 8.0.25, 5.7.34 test results
Attachment: 104245_5.6_5.7_8.0.results (application/octet-stream, text), 6.99 KiB.
[15 Oct 2021 18:31]
Marcos Albe
It looks even worse if you happen to use REPLACE INTO:
mysql [localhost:5734] {msandbox} (test) > DROP TABLE IF EXISTS t1;
Query OK, 0 rows affected (0.00 sec)
mysql [localhost:5734] {msandbox} (test) > CREATE TABLE `t1` (
-> `c1` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
-> `c2` bigint(20) NOT NULL,
-> `c3` bigint(20) NOT NULL,
-> `c4` bigint(20) NOT NULL,
-> `c5` bigint(20) NOT NULL,
-> PRIMARY KEY (`c1`),
-> UNIQUE KEY `UNIQUE_KEY` (`c2`,`c3`,`c4`)
-> ) ENGINE=InnoDB ;
Query OK, 0 rows affected (0.01 sec)
mysql [localhost:5734] {msandbox} (test) > INSERT IGNORE INTO t1 (c2, c3, c4, c5) values (1,1,1,1);
Query OK, 1 row affected (0.01 sec)
mysql [localhost:5734] {msandbox} (test) > BEGIN;
Query OK, 0 rows affected (0.00 sec)
mysql [localhost:5734] {msandbox} (test) > REPLACE INTO t1 (c2, c3, c4, c5) values (1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1);
Query OK, 10 rows affected (0.00 sec)
Records: 5 Duplicates: 5 Warnings: 0
mysql [localhost:5734] {msandbox} (test) > PAGER grep -A10 TRANSACTIONS; SHOW ENGINE INNODB STATUS\G NOPAGER;
PAGER set to 'grep -A10 TRANSACTIONS'
TRANSACTIONS
------------
Trx id counter 1333
Purge done for trx's n:o < 1333 undo n:o < 0 state: running but idle
History list length 8
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 1324, ACTIVE 27 sec
7 lock struct(s), heap size 1136, 34 row lock(s), undo log entries 10
MySQL thread id 3, OS thread handle 140427704448768, query id 45 localhost msandbox starting
SHOW ENGINE INNODB STATUS
...
The real problem is not seeing a large number in there, the problem is that when you do this a few thousand times within a transaction, latency of operations related to lock_mutex starts increasing dramatically:
When many duplicates are hit, people ends up with million of row locks:
---TRANSACTION 961918130, ACTIVE 558 sec inserting
mysql tables in use 1, locked 1
9558 lock struct(s), heap size 860368, 23485472 row lock(s)
We start seeing contention on LOCK_SYS:
--Thread 139748514125568 has waited at lock0lock.cc line 5938 for 0.00 seconds the semaphore:
Mutex at 0x7f15a3000058, Mutex LOCK_SYS created lock0lock.cc:446, lock var 1
--Thread 139762522830592 has waited at lock0lock.cc line 5938 for 0.00 seconds the semaphore:
Mutex at 0x7f15a3000058, Mutex LOCK_SYS created lock0lock.cc:446, lock var 1
And indeed, latency is an order of magnitude larger than any other mutex:
mysql> SELECT EVENT_NAME, COUNT_STAR, SUM_TIMER_WAIT, AVG_TIMER_WAIT FROM events_waits_summary_global_by_event_name where COUNT_STAR > 0 and EVENT_NAME like 'wait/synch/%' order by SUM_TIMER_WAIT desc limit 20;
+--------------------------------------------------+------------+-----------------+----------------+
| EVENT_NAME | COUNT_STAR | SUM_TIMER_WAIT | AVG_TIMER_WAIT |
+--------------------------------------------------+------------+-----------------+----------------+
| wait/synch/mutex/innodb/lock_mutex | 14402930 | 797432257360012 | 55365944 |
| wait/synch/sxlock/innodb/btr_search_latch | 118862154 | 10096372888696 | 84823 |
| wait/synch/sxlock/innodb/hash_table_locks | 151872933 | 8952263436564 | 58844 |
| wait/synch/sxlock/innodb/index_tree_rw_lock | 32520796 | 5101561615074 | 156813 |
| wait/synch/mutex/innodb/trx_mutex | 147506597 | 4561788758740 | 30674 |
| wait/synch/mutex/sql/THD::LOCK_thd_data | 102463613 | 3922012825582 | 38186 |
| wait/synch/mutex/sql/THD::LOCK_query_plan | 60053414 | 2665276338684 | 44133 |
| wait/synch/mutex/sql/LOCK_table_cache | 42209003 | 2546591308484 | 60096 |
We have already seen this happening to two different persons in the last couple of days.
Description: While inserting an existent row on a table within the same transaction row locks are duplicated after each insert. Probably these locks are related with MySQL locking the UK and PK at the same time. However, I can't see the same behavior on 8.0. How to repeat: mysql [localhost:4679] {msandbox} (test) > select @@version ; +-----------+ | @@version | +-----------+ | 5.7.34 | +-----------+ 1 row in set (0.00 sec) CREATE TABLE `t1` ( `c1` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `c2` bigint(20) NOT NULL, `c3` bigint(20) NOT NULL, `c4` bigint(20) NOT NULL, `c5` bigint(20) NOT NULL, PRIMARY KEY (`c1`), UNIQUE KEY `UNIQUE_KEY` (`c2`,`c3`,`c4`) ) ENGINE=InnoDB ; mysql [localhost:4679] {msandbox} (test) > INSERT IGNORE INTO t1 (c2, c3, c4, c5) values (1,1,1,1); Query OK, 1 row affected (0.00 sec) mysql [localhost:4679] {msandbox} (test) > BEGIN ; Query OK, 0 rows affected (0.00 sec) mysql [localhost:4679] {msandbox} (test) > INSERT IGNORE INTO t1 (c2, c3, c4, c5) values (1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1); Query OK, 0 rows affected, 5 warnings (0.00 sec) Records: 5 Duplicates: 5 Warnings: 5 mysql [localhost:4679] {msandbox} (test) > SHOW ENGINE INNODB STATUS\G ... ---TRANSACTION 1354, ACTIVE 24 sec 5 lock struct(s), heap size 1136, 10 row lock(s) MySQL thread id 3, OS thread handle 140062776764160, query id 468 localhost msandbox starting mysql [localhost:8025] {msandbox} (test) > select @@version ; +-----------+ | @@version | +-----------+ | 8.0.25 | +-----------+ 1 row in set (0.00 sec) CREATE TABLE `t1` ( `c1` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `c2` bigint(20) NOT NULL, `c3` bigint(20) NOT NULL, `c4` bigint(20) NOT NULL, `c5` bigint(20) NOT NULL, PRIMARY KEY (`c1`), UNIQUE KEY `UNIQUE_KEY` (`c2`,`c3`,`c4`) ) ENGINE=InnoDB ; mysql [localhost:8025] {msandbox} (test) > INSERT IGNORE INTO t1 (c2, c3, c4, c5) values (1,1,1,1); Query OK, 1 row affected (0.00 sec) mysql [localhost:8025] {msandbox} (test) > BEGIN ; Query OK, 0 rows affected (0.00 sec) mysql [localhost:8025] {msandbox} (test) > INSERT IGNORE INTO t1 (c2, c3, c4, c5) values (1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1),(1,1,1,1); Query OK, 0 rows affected, 5 warnings (0.00 sec) Records: 5 Duplicates: 5 Warnings: 5 mysql [localhost:8025] {msandbox} (test) > SHOW ENGINE INNODB STATUS\G ... ---TRANSACTION 1630, ACTIVE 20 sec 5 lock struct(s), heap size 1136, 2 row lock(s) MySQL thread id 11, OS thread handle 140440135558912, query id 109 localhost msandbox starting