MySQL Bugs: #49001: SHOW INNODB STATUS deadlock info incorrect when deadlock detection aborts

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	CPU Architecture:	Any
Tags:	deadlock, innodb, show innodb status

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).

is it restricted to 5.0 or do 5.1 and the Plugin suffer from this, too?

The code looks to be identical in 5.1 and the plugin, so I would imagine they will experience the same behavior.

I was able to repeat this using MySQL 5.1.41 both with and without the plugin as well.

History : show processlist and Least Dead lock

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

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

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.

Bug #49084 was closed as duplicate of this one.

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.

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.

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)

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)

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)

Pushed into mysql-next-mr (revid:alik@sun.com-20100302072432-k8xvfkgcggkwgi94) (version source revid:alik@sun.com-20100301094128-lohp5kgno1o5t6t6) (pib:16)

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)

The fix for this is in the InnoDB Plugin version 1.0.7 which was included with MySQL 5.1.46.

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)

Pushed into mysql-next-mr (revid:alik@sun.com-20100524190136-egaq7e8zgkwb9aqi) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (pib:16)

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)

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)

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)

Pushed into mysql-next-mr (revid:alik@sun.com-20100615080558-cw01bzdqr1bdmmec) (version source revid:mmakela@bk-internal.mysql.com-20100415070122-1nxji8ym4mao13ao) (pib:16)

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)

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)

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)

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).

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).