Constantly increasing Innodb_row_lock_current_waits value

[Dan Rogers]

I'm having the same problem described in http://bugs.mysql.com/bug.php?id=71520 in Percona Server 5.6

Here's my package info:

# rpm -qi Percona-Server-server-56
Name : Percona-Server-server-56
Version : 5.6.16
Release : rel64.2.el6
Architecture: x86_64
Install Date: Thu 27 Mar 2014 10:09:24 AM PDT
Group : Applications/Databases
Size : 90044320
License : Copyright (c) 2000, 2010, Oracle and/or its affiliates. All rights reserved. Use is subject to license terms. Under GPL license as shown in the Description field.
Signature : DSA/SHA1, Tue 25 Mar 2014 05:17:27 AM PDT, Key ID 1c4cbdcdcd2efd2a
Source RPM : Percona-Server-56-5.6.16-rel64.2.el6.src.rpm
Build Date : Mon 24 Mar 2014 09:17:46 AM PDT
Build Host : jhc-new-2-centos6-64.novalocal
Relocations : (not relocatable)
Packager : Percona MySQL Development Team <email address hidden>
Vendor : Percona, Inc
URL : http://www.percona.com/
Summary : Percona Server: a very fast and reliable SQL database server

Innodb_row_lock_current isn't being decremented sometimes:

mysql> show global status like 'Innodb_row_lock_current_waits';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 2 |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql> select count(*) from information_schema.innodb_lock_waits;
+----------+
| count(*) |
+----------+
| 0 |
+----------+
1 row in set (0.00 sec)

[Nilnandan Joshi (nilnandan-joshi)]

Unable to reproduce the same with 5.5.36 and 5.6.16
I tried to test by running sysbench with --num-threads=100 and got Innodb_row_lock_current_waits >0 but when test completes, it's set back to 0. So I don't see the behavior "Constantly increasing Innodb_row_lock_current_waits value "

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_6_16$ sysbench --test=oltp --oltp-table-size=1000000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=100 --max-time=90 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-socket=/tmp/mysql_sandbox5616.sock run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 100

Doing OLTP test.
Running mixed OLTP test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 99 times)
Done.

OLTP test statistics:
    queries performed:
        read: 2669604
        write: 953430
        other: 381372
        total: 4004406
    transactions: 190686 (2118.37 per sec.)
    deadlocks: 0 (0.00 per sec.)
    read/write requests: 3623034 (40248.94 per sec.)
    other operations: 381372 (4236.73 per sec.)

Test execution summary:
    total time: 90.0156s
    total number of events: 190686
    total time taken by event execution: 8998.5023
    per-request statistics:
         min: 4.23ms
         avg: 47.19ms
         max: 240.82ms
         approx. 95 percentile: 93.18ms

Threads fairness:
    events (avg/stddev): 1906.8600/21.21
    execution time (avg/stddev): 89.9850/0.01

nilnandan@nilnandan-Dell-XPS:~/sandboxes/msb_5_6_16$

mysql> show global status like 'innodb_row_lock_current_waits';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 2 |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql>

mysql> show global status like 'innodb_row_lock_current_waits';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 1 |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql>

mysql> show global status like 'innodb_row_lock_current_waits';
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| Innodb_row_lock_current_waits | 0 |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql>

[Chris Calender (chriscalender)]

I saw this occur just after a deadlock. The value for innodb_row_lock_current_waits has remained at a steady 26. Perhaps that could help in reproducing.

[Nilnandan Joshi (nilnandan-joshi)]

Hi Chris,

I have also tried with that option, where I have deliberately cause a deadlock and run above test. but couldn't able to reproduce your issue.

LATEST DETECTED DEADLOCK
------------------------
2014-07-29 14:45:13 7fe39d8f7700
*** (1) TRANSACTION:
TRANSACTION 3473, ACTIVE 4 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1184, 2 row lock(s)
MySQL thread id 52, OS thread handle 0x7fe39d8c6700, query id 1061 localhost root updating
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 5 n bits 144 index `PRIMARY` of table `dbtest`.`sbtest` trx id 3473 lock_mode X waiting
*** (2) TRANSACTION:
TRANSACTION 3471, ACTIVE 147 sec starting index read
mysql tables in use 1, locked 1
14536 lock struct(s), heap size 1537576, 2000834 row lock(s)
MySQL thread id 51, OS thread handle 0x7fe39d8f7700, query id 1062 localhost root Searching rows for update
update dbtest.sbtest set k = 0 where k <> 0
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 6 page no 5 n bits 144 index `PRIMARY` of table `dbtest`.`sbtest` trx id 3471 lock mode S locks rec but not gap
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 6 page no 5 n bits 144 index `PRIMARY` of table `dbtest`.`sbtest` trx id 3471 lock_mode X locks rec but not gap waiting
*** WE ROLL BACK TRANSACTION (1)

cause a deadlock from another two sessions even during the test.

nilnandan@nilnandan-Dell-XPS:~$ sysbench --test=oltp --oltp-table-size=1000000 --oltp-test-mode=complex --oltp-read-only=off --num-threads=100 --max-time=180 --max-requests=0 --mysql-db=dbtest --mysql-user=root --mysql-password=root run
sysbench 0.4.12: multi-threaded system evaluation benchmark

No DB drivers specified, using mysql
Running the test with following options:
Number of threads: 100

Doing OLTP test.
Running mixed OLTP test
Using Special distribution (12 iterations, 1 pct of values are returned in 75 pct cases)
Using "BEGIN" for starting transactions
Using auto_inc on the id column
Threads started!
Time limit exceeded, exiting...
(last message repeated 99 times)
Done.

OLTP test statistics:
    queries performed:
        read: 1348802
        write: 480865
        other: 192451
        total: 2022118
    transactions: 96108 (533.69 per sec.)
    deadlocks: 235 (1.30 per sec.)
    read/write requests: 1829667 (10160.10 per sec.)
    other operations: 192451 (1068.68 per sec.)

Test execution summary:
    total time: 180.0835s
    total number of events: 96108
    total time taken by event execution: 18001.7449
    per-request statistics:
         min: 5.19ms
         avg: 187.31ms
         max: 106460.04ms
         approx. 95 percentile: 150.12ms

Threads fairness:
    events (avg/stddev): 961.0800/12.15
    execution time (avg/stddev): 180.0174/0.02

nilnandan@nilnandan-Dell-XPS:~$

Ini...

[Chris Calender (chriscalender)]

Hi Nilnandan,

Thank you for attempting to reproduce this. I've been unable to reproduce this as well - spent quite a few hours/days, even on some older versions.

I mimic'ed the deadlock, down to the exact table (w/ partitions), exact statements, same order, same locks/lock states by the preceding statements in the transactions (i.e., the statements holding the locks leading to the deadlock), the number of innodb_current_row_lock_waits, etc. No matter what I've tried, innodb_current_row_lock_waits remains the same.

It's so minor, I'm hanging up trying to reproduce this.

Thanks again. :)

Best wishes,
Chris

[Nilnandan Joshi (nilnandan-joshi)]

Hi Chris, Thanks for update. Please let us know if you can found repeatable test case.

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-3119