[MDEV-14400] Innodb_row_lock_current_waits increases to 18446744073709551615 Created: 2017-11-15  Updated: 2017-11-22

Status: Open
Project: MariaDB Server
Component/s: Locking, Storage Engine - InnoDB
Affects Version/s: 10.1.22
Fix Version/s: None

Type: Bug Priority: Major
Reporter: M.Lauterbach Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Environment:

mysql Ver 15.1 Distrib 10.1.22-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
Linux HOST 4.4.0-97-generic #120-Ubuntu SMP Tue Sep 19 17:28:18 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

Attachments: File galera.cnf     PNG File last_hour.png     PNG File last_months.png     PNG File last_week.png     PNG File last_weeks.png     File my.cnf     PNG File mysql_innodb_data_pending_fsyncs_20171122_0200-0300.png     PNG File mysql_process_runtime_20171122_0200-0300.png     PNG File mysql_threads_connected_20171122_0200-0300.png     PNG File mysql_threads_running_20171122_0200-0300.png     HTML File show_status_20171122-0941    

 Description   

Innodb_row_lock_current_waits increases rapidly from 0 to 18446744073709551615 and does not lower again.

As you can see, this happens very fast and it has been happening more than once.

Monitoring last hour

Monitoring current week

Monitoring last weeks

Monitoring last months

MariaDB [(none)]> show status like '%Innodb_row_lock_current%';
 
+-------------------------------+----------------------+
 
| Variable_name                 | Value                |
 
+-------------------------------+----------------------+
 
| Innodb_row_lock_current_waits | 18446744073709551615 |
 
+-------------------------------+----------------------+
 
1 row in set (0.00 sec)
 
 
 
MariaDB [(none)]> select count(*) from information_schema.innodb_lock_waits;
 
+----------+
 
| count(*) |
 
+----------+
 
|        0 |
 
+----------+
 
1 row in set (0.00 sec)
 
 
 
MariaDB [(none)]> select version();
 
+--------------------------+
 
| version()                |
 
+--------------------------+
 
| 10.1.22-MariaDB-1~xenial |
 
+--------------------------+
 
1 row in set (0.00 sec)

Here, I dumped my environment.

MariaDB [(none)]> show status;
 
+--------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------+
 
| Variable_name                                                | Value                                                                                                             |
 
+--------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------+
 
| wsrep_connected                                              | ON                                                                                                                |
 
| wsrep_evs_state                                              | OPERATIONAL                                                                                                       |
 
| wsrep_local_state_comment                                    | Synced                                                                                                            |
 
| wsrep_provider_name                                          | Galera                                                                                                            |
 
| wsrep_provider_vendor                                        | Codership Oy <info@codership.com>                                                                                 |
 
| wsrep_provider_version                                       | 25.3.19(r3667)                                                                                                    |
 
| wsrep_ready                                                  | ON                                                                                                                |



 Comments   
Comment by Elena Stepanova [ 2017-11-20 ]

SelectNameFromDual, on some reason show status that you pasted only contains a few wsrep variables. Please attach the whole output, and also your cnf file(s).
From the wsrep output, I assume you are using the Galera cluster. Does it happen on all cluster nodes?
How active is the server where the problem occurs, how many connections it serves simultaneously?
Do you have any idea of what happens on the node around the time when the value jumps? If you have the general log enabled, matching its timestamps with your monitoring output might help.
You mentioned that the value does not go back, but on graphs it does, after a while – how does it happen, do you restart the server or do anything else?
What does the error log say, is there anything suspicious around the time?

Thanks.

Comment by M.Lauterbach [ 2017-11-22 ]

_elenst said:

Please attach the whole output, and also your cnf file(s).


I created a new status and attached it as a file. show_status_20171122-0941, galera.cnf, my.cnf

_elenst said:


From the wsrep output, I assume you are using the Galera cluster. Does it happen on all cluster nodes?

Your assumption is correct. I am using Galera cluster . And currently this problem only happens on one of the cluster nodes. Since the server entered this state, I did not restart the node. Up to now, every night this state flickers.

Time State reported
until Wed Nov 22 02:11:10 CET 2017 18446744073709551615
Wed Nov 22 02:11:10 CET 2017 0
Wed Nov 22 02:15:10 CET 2017 18446744073709551615
Wed Nov 22 02:20:10 CET 2017 1
Wed Nov 22 02:23:09 CET 2017 18446744073709551615

_elenst said:

How active is the server where the problem occurs, how many connections it serves simultaneously?


Due to my monitoring, I got several insights to the time, when the state changes.
Innodb data pending fsyncs

Threads connected

Threads running

Process runtime

Entries in mysqld-error.log

2017-11-21 18:56:13 140344217827072 [Note] WSREP: (444c2b33, 'ssl://0.0.0.0:4567') turning message relay requesting off
 
2017-11-22  2:12:41 140344267388672 [Warning] WSREP: Failed to report last committed 2815717609, -4 (Interrupted system call)
 
2017-11-22  2:12:52 140344267388672 [Warning] WSREP: Failed to report last committed 2815717765, -4 (Interrupted system call)
 
2017-11-22  4:39:16 140353528101632 [Note] InnoDB: Online DDL : Start

I asked my developers colleagues if they might have a clue, which kind of statements run at this time. Up to now, they do not have a guess.

Generated at Thu Feb 08 08:13:15 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.