Bug #110101 lock_row_lock_current_waits counter in innodb_metrics goes negative
Description:
In concurrent environment we may end up with a negative value of the lock_row_lock_current_waits counter (see how to repeat for the details on one way to do this):
mysql> select name, count,time_enabled from information_schema.innodb_metrics where name ='lock_row_lock_current_waits';
+-----------------------------+-------+---------------------+
| name | count | time_enabled |
+-----------------------------+-------+---------------------+
| lock_row_lock_current_waits | -1 | 2023-02-16 17:18:53 |
+-----------------------------+-------+---------------------+
1 row in set (0,00 sec)
This is a bug. There were several similar bugs reported (and some fixed), see https://bugs.mysql.com/bug.php?id=81099
How to repeat:
Consider the following test case that requires 3 sessions. In the first session run these:
mysql> set global innodb_lock_wait_timeout=50;
Query OK, 0 rows affected (0,03 sec)
mysql> CREATE TABLE `test` (`col` varchar(10) ) engine=InnoDB;
insert into test values ('a');
select name, count,time_enabled from information_schema.innodb_metrics where name ='lock_row_lock_current_waits';
Query OK, 0 rows affected (0,50 sec)
Query OK, 1 row affected (0,19 sec)
+-----------------------------+-------+---------------------+
| name | count | time_enabled |
+-----------------------------+-------+---------------------+
| lock_row_lock_current_waits | 0 | 2023-02-16 17:01:24 |
+-----------------------------+-------+---------------------+
1 row in set (0,08 sec)
Now start transaction and update the only row in this table from the second session:
mysql> begin;update test set col='c' where col='a';
Query OK, 0 rows affected (0,00 sec)
Query OK, 1 row affected (0,01 sec)
Rows matched: 1 Changed: 1 Warnings: 0
In the third session try to update the same row:
mysql> begin;update test set col='b' where col='a';
Back in the first session we see counter increased, as the third session waits:
mysql> select name, count,time_enabled from information_schema.innodb_metrics where name ='lock_row_lock_current_waits';
+-----------------------------+-------+---------------------+
| name | count | time_enabled |
+-----------------------------+-------+---------------------+
| lock_row_lock_current_waits | 1 | 2023-02-16 17:01:24 |
+-----------------------------+-------+---------------------+
1 row in set (0,00 sec)
No, resent the counter globally:
mysql> set global innodb_monitor_disable='lock_row_lock_current_waits';
set global innodb_monitor_reset_all='lock_row_lock_current_waits';
set global innodb_monitor_enable='lock_row_lock_current_waits';
Query OK, 0 rows affected (0,00 sec)
Query OK, 0 rows affected (0,00 sec)
Query OK, 0 rows affected (0,00 sec)
and the value is back to zero:
mysql> select name, count,time_enabled from information_schema.innodb_metrics where name ='lock_row_lock_current_waits';
+-----------------------------+-------+---------------------+
| name | count | time_enabled |
+-----------------------------+-------+---------------------+
| lock_row_lock_current_waits | 0 | 2023-02-16 17:18:53 |
+-----------------------------+-------+---------------------+
1 row in set (0,00 sec)
Now wait until UPDATE in the third session fails with lock wait timeout error:
Query OK, 0 rows affected (0,00 sec)
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
and try again the first session:
mysql> select name, count,time_enabled from information_schema.innodb_metrics where name ='lock_row_lock_current_waits';
+-----------------------------+-------+---------------------+
| name | count | time_enabled |
+-----------------------------+-------+---------------------+
| lock_row_lock_current_waits | -1 | 2023-02-16 17:18:53 |
+-----------------------------+-------+---------------------+
1 row in set (0,00 sec)
Suggested fix:
Make sure negative values never appear in the information_schema.innodb_metrics table. Or remove the feature entirely if it's so buggy and no longer important.
Portions of this website are copyright © 2001, 2002 The PHP Group
Page generated in 0.041 sec. using MySQL 8.4.7-u6-cloud
Timestamp references displayed by the system are UTC.
Content reproduced on this site is the property of the
respective copyright holders.
It is not reviewed in advance
by Oracle and does not necessarily represent the opinion of
Oracle or any other party.