Bug #49001 SHOW INNODB STATUS deadlock info incorrect when deadlock detection aborts
Submitted: 23 Nov 2009 20:29 Modified: 27 Jul 2010 21:17
Reporter: Harrison Fisk Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.0,5.1,5.1 with plugin OS:Any
Assigned to: Jimmy Yang
Tags: deadlock, innodb, show innodb status
Triage: Triaged: D3 (Medium)

[23 Nov 2009 20:29] Harrison Fisk
Description:
InnoDB aborts deadlock detection when it finds more than 200 locks in that section of the lock graph.  However, when it does this it records incorrect information in the LATEST DETECTED DEADLOCK section.

How to repeat:
CREATE TABLE test.t1 (a int) ENGINE=InnoDB;
INSERT INTO test.t1 VALUES (5);
SET GLOBAL max_connections = 500;

for i in {1..300}; do ( yes "UPDATE t1 SET a=$i;" | mysql -S /tmp/mysql.sock test & ) ; done

In another connection do:

SHOW INNODB STATUS\G
SHOW PROCESSLIST;

Look at the 'killed' thread in SHOW INNODB STATUS.  See it is still in SHOW PROCESSLIST.

Suggested fix:
In the file innobase/lock/lock0lock.c there is a function 'lock_deadlock_recursive' which says which to print as:

                        ibool   too_far
                                = depth > LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK
                                || *cost > LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK;

                        lock_trx = lock->trx;

                        if (lock_trx == start || too_far) {

                                ...

                                fputs("\n*** (1) TRANSACTION:\n", ef);

                                trx_print(ef, wait_lock->trx, 3000);

                                ...

                                trx_print(ef, lock->trx, 3000);

                                fputs("*** (2) HOLDS THE LOCK(S):\n", ef);
                        }

The problem is that when lock_trx != start (which happens when too_far is set), then the second transaction printed isn't the one being rolled back.  The second one should be changed to print start->trx I believe (since LOCK_VICTIM_IS_START is returned).
[24 Nov 2009 14:42] Mikhail Izioumtchenko
is it restricted to 5.0 or do 5.1 and the Plugin suffer from this, too?
[24 Nov 2009 14:45] Harrison Fisk
The code looks to be identical in 5.1 and the plugin, so I would imagine they will experience the same behavior.
[24 Nov 2009 15:12] Harrison Fisk
I was able to repeat this using MySQL 5.1.41 both with and without the plugin as well.
[25 Nov 2009 5:50] He yunfei
History : show processlist and Least Dead lock

Attachment: Show processlists.log (application/octet-stream, text), 364.53 KiB.

[25 Nov 2009 12:37] Jimmy Yang
Most Harrison's analysis are correct. In most deadlock case, we shall find a circular ring, where the transaction wait graph leads us to its starting point, so if we decide the currrent transcation is the one to be killed, it is the same as the start transactoin. And the print of "trx_print(ef, lock->trx, 3000)" is equivalent to trx_print(ef, start, 3000);

However, since lock_deadlock_recursive() is a recursive funtion, if we abort the search due to depth exceeds LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK or cost exceeds LOCK_MAX_N_STEPS_IN_DEADLOCK_CHECK, the printing is happening at the bottom of the recursive tree, after that, the function will unwind all the way up, and the "start" transaction is the one to be killed. So the 
lock->trx is really not the same as "start" (note start is already the transaction).

In such case, the fix for transaction is relatively easy, we could change "trx_print(ef, lock->trx, 3000)" to trx_print(ef, start, 3000), however, the locks it(start) owns will not be the same as the one in the bottom of the recursive tree where we printing it. Either we shall withhold from printing it (as it is not a true deadlock), or we could return a new status all the way up to print it in the top level.

Thanks
Jimmy
[3 Dec 2009 12:47] Jimmy Yang
When deadlock search aborted due to search graph exceeds max depth and cost, print the victim transaction at the root level of the search operation.
[24 Dec 2009 8:44] Sveta Smirnova
Bug #49084 was closed as duplicate of this one.
[3 Feb 2010 1:54] Jimmy Yang
r6545 | jyang | 2010-02-02 17:57:32 -0800 (Tue, 02 Feb 2010) | 8 lines

branches/5.1: Fix bug #49001, "SHOW INNODB STATUS deadlock info
incorrect when deadlock detection aborts". Print the correct
lock owner when recursive function lock_deadlock_recursive()
exceeds its maximum depth LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK.
[26 Feb 2010 9:04] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/101561

3362 Sergey Vojtovich	2010-02-26
      Applying InnoDB snapshot, fixes BUG#49001
      
      Detailed revision comments:
      
      r6545 | jyang | 2010-02-03 03:57:32 +0200 (Wed, 03 Feb 2010) | 8 lines
      branches/5.1: Fix bug #49001, "SHOW INNODB STATUS deadlock info
      incorrect when deadlock detection aborts". Print the correct
      lock owner when recursive function lock_deadlock_recursive()
      exceeds its maximum depth LOCK_MAX_DEPTH_IN_DEADLOCK_CHECK.
      
      rb://217, approved by Marko.
[1 Mar 2010 8:47] Bugs System
Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:svoj@sun.com-20100226123413-rrzvxtm09jy39a9w) (merge vers: 5.1.45) (pib:16)
[2 Mar 2010 14:34] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100302142746-u1gxdf5yk2bjrq3e) (version source revid:alik@sun.com-20100301095421-4cz64ibem1h2quve) (merge vers: 6.0.14-alpha) (pib:16)
[2 Mar 2010 14:41] Bugs System
Pushed into 5.5.3-m2 (revid:alik@sun.com-20100302072233-t3uqgjzdukt1pyhe) (version source revid:alexey.kopytov@sun.com-20100226131009-mch7mua4vfxs2bno) (merge vers: 5.5.3-m2) (pib:16)
[2 Mar 2010 14:46] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100301094128-lohp5kgno1o5t6t6) (pib:16)
[6 Apr 2010 8:01] Bugs System
Pushed into 5.1.46 (revid:sergey.glukhov@sun.com-20100405111026-7kz1p8qlzglqgfmu) (version source revid:svoj@sun.com-20100401151005-c6re90vdvutln15d) (merge vers: 5.1.46) (pib:16)
[28 Apr 2010 4:09] James Day
The fix for this is in the InnoDB Plugin version 1.0.7 which was included with MySQL 5.1.46.
[5 May 2010 15:27] Bugs System
Pushed into 5.1.47 (revid:joro@sun.com-20100505145753-ivlt4hclbrjy8eye) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 5:52] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)
[28 May 2010 6:22] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100524190941-nuudpx60if25wsvx) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[28 May 2010 6:50] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100524185725-c8k5q7v60i5nix3t) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[15 Jun 2010 8:22] Bugs System
Pushed into 5.5.5-m3 (revid:alik@sun.com-20100615080459-smuswd9ooeywcxuc) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (merge vers: 5.1.47) (pib:16)
[15 Jun 2010 8:40] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)
[17 Jun 2010 11:53] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:30] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 13:18] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[27 Jul 2010 21:16] John Russell
Added to the 5.1.45 and 5.5.3 change log:

SHOW INNODB STATUS could display incorrect information about deadlocks,
when the deadlock detection routine stops early (to avoid excessive CPU usage).
[29 Oct 2012 1:48] Franjo Markovic
I just got a very similar situation in 5.6.4. Did this patch go into 5.6 branch? (I apologize if there is a fix already in 5.6.5 or later - cannot upgrade at a moment).