Bug #110101 lock_row_lock_current_waits counter in innodb_metrics goes negative

Submitted: 16 Feb 2023 15:32 Modified: 17 Feb 2023 12:32
Reporter: Valeriy Kravchuk Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.7.39, 8.0, 8.0.32 OS:Any
Assigned to: CPU Architecture:Any
Tags: information_schema, innodb_metrics

[16 Feb 2023 15:32] Valeriy Kravchuk
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.
[17 Feb 2023 12:32] MySQL Verification Team
Dear Valeriy,

Thank you for the report and feedback.
Verified as described.

regards,
Umesh

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.