| Summary: | innodb_print_all_deadlocks turned ON shows no deadlock errors in SHOW engine innodb status or logs | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Ajay Kalambur <akalambu> |
| Component: | mariadb | Assignee: | Michal Schorm <mschorm> |
| Status: | CLOSED NOTABUG | QA Contact: | qe-baseos-daemons |
| Severity: | medium | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 7.2 | CC: | akalambu, databases-maint, hhorak, kvolny, mbayer, srevivo |
| Target Milestone: | pre-dev-freeze | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | All | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2017-03-14 16:45:33 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Bug Depends On: | |||
| Bug Blocks: | 1346768 | ||
|
Description
Ajay Kalambur
2016-10-12 17:31:22 UTC
I have a few questions here: 1. is this using galera? I noticed you put mariadb-5.5.50 as the package, not galera. 2. what kind of forced deadlock is this? It seems that "show engine innodb status" intends to show previous deadlocks that are no longer in play, however Galera will throw error 1213 for some of its own conditions that may not be covered by this. For example, I just ran the steps at http://dev.mysql.com/doc/refman/5.7/en/innodb-deadlock-example.html using our current mariadb-galera-5.5.42 package. After receiving the 1213, "show engine innodb status" includes the information: ------------------------ LATEST DETECTED DEADLOCK ------------------------ 2016-10-12 14:08:38 7f4b188e0700 *** (1) TRANSACTION: TRANSACTION 732535, ACTIVE 12 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 360, 1 row lock(s) MySQL thread id 2445, OS thread handle 0x7f4b1940c700, query id 2471853 localhost root updating DELETE FROM t WHERE i = 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 762 page no 3 n bits 72 index `GEN_CLUST_INDEX` of table `mike_test`.`t` trx table locks 1 total table locks 3 trx id 732535 lock_mode X waiting lock hold time 12 wait time before grant 0 *** (2) TRANSACTION: TRANSACTION 732356, ACTIVE 29 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1184, 3 row lock(s) MySQL thread id 2441, OS thread handle 0x7f4b188e0700, query id 2472550 localhost root updating DELETE FROM t WHERE i = 1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 762 page no 3 n bits 72 index `GEN_CLUST_INDEX` of table `mike_test`.`t` trx table locks 2 total table locks 3 trx id 732356 lock mode S lock hold time 29 wait time before grant 0 *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 762 page no 3 n bits 72 index `GEN_CLUST_INDEX` of table `mike_test`.`t` trx table locks 2 total table locks 3 trx id 732356 lock_mode X waiting lock hold time 0 wait time before grant 0 *** WE ROLL BACK TRANSACTION (1) would need full reproduction steps, as well as clarification on software in use. correction, those were on mariadb-server-10.1. Nevertheless, need some reproduction steps. I ran the exact same sequence of steps on my mariadb server and i dont see the Latest deadlock section in show engine innodb status output http://dev.mysql.com/doc/refman/5.7/en/innodb-deadlock-example.html My version is from rhel7-server-rpms Name : mariadb-server Arch : x86_64 Epoch : 1 Version : 5.5.50 Release : 1.el7_2 Size : 11 M Repo : rhel-7-server-rpms Summary : The MariaDB server and related files URL : http://mariadb.org License : GPLv2 with exceptions and LGPLv2 and BSD Description : MariaDB is a multi-user, multi-threaded SQL database server. It is a : client/server implementation consisting of a server daemon (mysqld) : and many different client programs and libraries. This package contains : the MariaDB server and some accompanying files and directories. : MariaDB is a community developed branch of MySQL. OK so this is not galera then, however I will try out 5.5.50 right now to get some more data on this anyway. okey doke, just tried 5.5.52 which is the latest build we have for the 7.3 release candidates: mariadb-5.5.52-1.el7.x86_64 mariadb-server-5.5.52-1.el7.x86_64 mariadb-libs-5.5.52-1.el7.x86_64 ran the deadlock test and I get this back: ------------------------ LATEST DETECTED DEADLOCK ------------------------ 161012 15:56:13 *** (1) TRANSACTION: TRANSACTION 304, ACTIVE 14 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 3, OS thread handle 0x7f1e80081700, query id 20 localhost root updating DELETE FROM t WHERE i = 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 308 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 304 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 303, ACTIVE 26 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1248, 3 row lock(s) MySQL thread id 2, OS thread handle 0x7f1e800ca700, query id 21 localhost root updating DELETE FROM t WHERE i = 1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 308 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 303 lock mode S *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 308 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 303 lock_mode X waiting *** WE ROLL BACK TRANSACTION (1) I'm going to try downgrading specifically to 5.5.50 and see if this changes. here's the same test with 5.5.50-1.el7_2: mariadb-5.5.50-1.el7_2.x86_64 mariadb-libs-5.5.50-1.el7_2.x86_64 mariadb-server-5.5.50-1.el7_2.x86_64 ------------------------ LATEST DETECTED DEADLOCK ------------------------ 161012 16:10:26 *** (1) TRANSACTION: TRANSACTION 304, ACTIVE 4 sec starting index read etc. however, note that these are plain vanilla installs, without setting "innodb_print_all_deadlocks" - the default my.cnf.d/ files are all essentially blank of any configuration options. Running with innodb_print_all_deadlocks turned on, reading at http://dev.mysql.com/doc/refman/5.7/en/innodb-parameters.html#sysvar_innodb_print_all_deadlocks, first off the purpose of this flag is not that you'd see more in "LATEST DETECTED DEADLOCK", it's that all the deadlocks would be written to the error log. And I see that also. Running the test twice again with the flag, LATEST DETECTED is updated: ------------------------ LATEST DETECTED DEADLOCK ------------------------ 161012 16:20:48 *** (1) TRANSACTION: TRANSACTION 514, ACTIVE 4 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) .. etc then in /var/log/mariadb/mariadb.log, we see the logging as expected InnoDB: transactions deadlock detected, dumping detailed information. 161012 16:19:17 *** (1) TRANSACTION: TRANSACTION 505, ACTIVE 4 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 3, OS thread handle 0x7fbb080cd700, query id 22 localhost root updating DELETE FROM t WHERE i = 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 311 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 505 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 504, ACTIVE 12 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1248, 3 row lock(s) MySQL thread id 2, OS thread handle 0x7fbb08116700, query id 23 localhost root updating DELETE FROM t WHERE i = 1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 311 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 504 lock mode S *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 311 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 504 lock_mode X waiting *** WE ROLL BACK TRANSACTION (1) InnoDB: transactions deadlock detected, dumping detailed information. 161012 16:20:48 *** (1) TRANSACTION: TRANSACTION 514, ACTIVE 4 sec starting index read mysql tables in use 1, locked 1 LOCK WAIT 2 lock struct(s), heap size 376, 1 row lock(s) MySQL thread id 3, OS thread handle 0x7fbb080cd700, query id 52 localhost root updating DELETE FROM t WHERE i = 1 *** (1) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 315 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 514 lock_mode X waiting *** (2) TRANSACTION: TRANSACTION 513, ACTIVE 8 sec starting index read mysql tables in use 1, locked 1 4 lock struct(s), heap size 1248, 3 row lock(s) MySQL thread id 2, OS thread handle 0x7fbb08116700, query id 53 localhost root updating DELETE FROM t WHERE i = 1 *** (2) HOLDS THE LOCK(S): RECORD LOCKS space id 0 page no 315 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 513 lock mode S *** (2) WAITING FOR THIS LOCK TO BE GRANTED: RECORD LOCKS space id 0 page no 315 n bits 72 index `GEN_CLUST_INDEX` of table `test`.`t` trx id 513 lock_mode X waiting *** WE ROLL BACK TRANSACTION (1) Can you please check that nothing has been logged in /var/log/mariadb/mariadb.log (also confirming this is your log location in /etc/my.cnf) and please share all your /etc/my.cnf* files please? Ajay, any updates about question asked in comment #7? Issue not seen any more. |