MySQL Bugs: #27276: InnoDB Error: ibuf cursor restoration fails

Bug #27276	InnoDB Error: ibuf cursor restoration fails
Submitted:	19 Mar 2007 22:22	Modified:	20 Jun 2010 0:47
Reporter:	Axel Schwenke	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.0.26, 5.1	OS:	Linux (Linux)
Assigned to:	Satya B	CPU Architecture:	Any

Description:
InnoDB emits messages to the MySQL error log:

InnoDB: ERROR: Submit the output to http://bugs.mysql.com
InnoDB: ibuf cursor restoration fails!
InnoDB: ibuf record inserted to page 746563
PHYSICAL RECORD: n_fields 15; 1-byte offsets; info bits 0
 0: len 4; hex 0000023e; asc    >;; 1: len 1; hex 00; asc  ;; 2: len 4; hex 000b6442; asc   dB;; 3: len 30; hex 00860300048000860c00088000010f006480088603000480008602000280; asc                 d             ;...(truncated); 4: len 4; hex d364213d; asc  d!=;; 5: len 8; hex 80001240fc1f8110; asc    @    ;; 6: len 10; hex 43494444383033393535; asc CIDD803955;; 7: len 4; hex 000033dc; asc   3 ;; 8: len 2; hex 0006; asc   ;; 9: len 4; hex 000001d2; asc     ;; 10: len 2; hex 22b8; asc " ;; 11: len 1; hex 03; asc  ;; 12: len 4; hex a1330000; asc  3  ;; 13: len 1; hex 82; asc  ;; 14: len 4; hex d186bf32; asc    2;;
PHYSICAL RECORD: n_fields 15; 1-byte offsets; info bits 0
 0: len 4; hex 0000023e; asc    >;; 1: len 1; hex 00; asc  ;; 2: len 4; hex 000b6442; asc   dB;; 3: len 30; hex 00860300048000860c00088000010f006480088603000480008602000280; asc                 d             ;...(truncated); 4: len 4; hex d364213d; asc  d!=;; 5: len 8; hex 80001240fc1f8110; asc    @    ;; 6: len 10; hex 43494444383033393535; asc CIDD803955;; 7: len 4; hex 000033dc; asc   3 ;; 8: len 2; hex 0006; asc   ;; 9: len 4; hex 000001d2; asc     ;; 10: len 2; hex 22b8; asc " ;; 11: len 1; hex 03; asc  ;; 12: len 4; hex a1330000; asc  3  ;; 13: len 1; hex 82; asc  ;; 14: len 4; hex d186bf32; asc    2;;
DATA TUPLE: 3 fields;
 0: len 4; hex 0000023e; asc    >;; 1: len 1; hex 00; asc  ;; 2: len 4; hex 000b6443; asc   dC;;
PHYSICAL RECORD: n_fields 15; 1-byte offsets; info bits 0
 0: len 4; hex 0000023e; asc    >;; 1: len 1; hex 00; asc  ;; 2: len 4; hex 000b6443; asc   dC;; 3: len 30; hex 00860300048000860c00088000010f006480088603000480008602000280; asc                 d             ;...(truncated); 4: len 4; hex d364213d; asc  d!=;; 5: len 8; hex 80001240fc1fa820; asc    @    ;; 6: len 10; hex 43494444383033393535; asc CIDD803955;; 7: len 4; hex 000033dc; asc   3 ;; 8: len 2; hex 0006; asc   ;; 9: len 4; hex 000001d2; asc     ;; 10: len 2; hex 0058; asc  X;; 11: len 1; hex 03; asc  ;; 12: len 4; hex a1330000; asc  3  ;; 13: len 1; hex 82; asc  ;; 14: len 4; hex d186bf32; asc    2;;
InnoDB: Validating insert buffer tree:
InnoDB: ibuf tree ok

How to repeat:
This happened for the first time, but multiple times in succession. I have no idea what caused it.

Maybe the same bug as http://bugs.mysql.com/bug.php?id=28112

Marko,

please look at this.

--Heikki

Hmm, these errors are reported by ibuf_delete_rec(), which deletes a record from the insert buffer once it has been inserted to a secondary index of a table. Usually, it is an optimistic delete, meaning that the insert buffer B-tree is not contracted. This error appears to occur when preparing for a pessimistic delete in ibuf_delete_rec():

	/* We have to resort to a pessimistic delete from ibuf */
	btr_pcur_store_position(pcur, mtr);

	btr_pcur_commit_specify_mtr(pcur, mtr);

	/* Currently the insert buffer of space 0 takes care of inserts to all
	tablespaces */

	ibuf_data = fil_space_get_ibuf_data(0);

	mutex_enter(&ibuf_mutex);

	mtr_start(mtr);

	success = btr_pcur_restore_position(BTR_MODIFY_TREE, pcur, mtr);

We must commit and restart the mini-transaction, so that the pessimistic delete will not break the latching order (which could lead to a deadlock).

The problem is that somehow the record that we are attempting to delete would disappear before btr_pcur_restore_position(). Is it possible that some other thread could have deleted this record?

I am assigning this bug to Heikki, because he knows the insert buffer subsystem better than me. Heikki, feel free to reassign this bug back to me once you have answered my question.

Marko,

hmm... maybe if the table is dropped, then the record can get deleted meanwhile.

Need to study this more.

Regards,

Heikki

Anyone seen this since May 2007?
--Heikki

When InnoDB is low on the insert buffer, ibuf_insert_low() may call buf_read_ibuf_merge_pages() to contract the insert buffer and to merge the buffered changes to secondary indexes. If it selects changes for a tablespace (*.ibd file) that has been dropped (e.g., DROP TABLE), the unbuffered changes can and will be discarded.

In rare circumstances it is possible that multiple threads happen to be invoking buf_read_ibuf_merge_pages() at the same time from ibuf_insert_low(), and they attempt to discard the buffered changes to the same page in the discarded tablespace. The function ibuf_delete_rec() may then complain that the insert buffer record has disappeared (it has been deleted by another thread).

This warning is harmless when the tablespace has been discarded, and we should suppress it in that case.

This bug is very hard to repeat, even though it has apparently existed since the dawn of innodb_file_per_table. It requires a workload that fills the insert buffer and drops tables for which there are buffered changes. I have been unable to repeat this in the standard MySQL/InnoDB, but I ran across this bug in the InnoDB plugin when using compressed tables.

There is a bug in the bug fix: ibuf_delete_rec() forgets to commit mtr when the tablespace has been dropped. Thus, it would keep the ibuf->index->lock X-latched, which may lead into a deadlock (resolved by the 10-minute watchdog killing the server).

The fix is simple:

Index: ibuf/ibuf0ibuf.c
===================================================================
--- ibuf/ibuf0ibuf.c	(revision 3584)
+++ ibuf/ibuf0ibuf.c	(working copy)
@@ -2996,7 +2996,7 @@ ibuf_delete_rec(
 			/* The tablespace has been dropped.  It is possible
 			that another thread has deleted the insert buffer
 			entry.  Do not complain. */
-			goto func_exit;
+			goto commit_and_exit;
 		}
 
 		fprintf(stderr,
@@ -3041,6 +3041,7 @@ ibuf_delete_rec(
 
 	ut_ad(ibuf_validate_low());
 
+commit_and_exit:
 	btr_pcur_commit_specify_mtr(pcur, mtr);
 
 func_exit:

Ok to commit the fix.

Docs team:  This bug is fixed in 6.0.11.  Please return to 'Patch Approved', pending decision on putting it in 5.1.

Noted in 6.0.11 changelog.

For InnoDB tables that have their own .ibd tablespace file, a
superfluous ibuf cursor restoration fails! message could be written
to the error log. This warning has been suppressed.

Setting report to Patch Approved pending possible push into 5.1.x.

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/72485

2860 Satya B	2009-04-20
      Applying InnoDB snashot 5.1-ss3603. Fixes BUG#27276
      
      1) BUG#27276 - InnoDB Error: ibuf cursor restoration fails
      
      2) Follow up fix for BUG#27276 which fixes the bug introduced in
         the previous revision r2924
      
      Detailed revision comments:
      
      r2924 | marko | 2008-10-29 10:07:48 +0200 (Wed, 29 Oct 2008) | 7 lines
      branches/5.1: Merge revision 2866 from branches/zip:
      
      ibuf_delete_rec(): When the cursor to the insert buffer record cannot be
      restored, do not complain if the tablespace does not exist. (Bug #27276)
      
      Approved by Sunny Bains (rb://34)
      
      r3598 | marko | 2008-12-22 15:28:03 +0200 (Mon, 22 Dec 2008) | 6 lines
      branches/5.1: ibuf_delete_rec(): When the record cannot be found and
      the tablespace has been dropped, commit the mini-transaction, so that
      InnoDB will not hold the insert buffer tree latch in exclusive mode,
      causing a potential deadlock.  This bug was introduced in the fix of
      Bug #27276 in r2924.
      modified:
        storage/innobase/ibuf/ibuf0ibuf.c

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/72487

3220 Satya B	2009-04-20 [merge]
      NULL MERGE of innodb-5.1-ss3603,BUG#27276 into 6.0 branch

Pushed into 5.1.35 (revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (version source revid:davi.arnaut@sun.com-20090505190206-9xmh7dlc6kom8exp) (merge vers: 5.1.35) (pib:6)

Pushed into 6.0.12-alpha (revid:svoj@sun.com-20090506125450-yokcmvqf2g7jhujq) (version source revid:aelkin@mysql.com-20090421094803-hho7a34gdsby7382) (merge vers: 6.0.11-alpha) (pib:6)

Noted in 5.1.35 changelog.

Pushed into 5.1.35-ndb-6.3.26 (revid:jonas@mysql.com-20090615074202-0r5r2jmi83tww6sf) (version source revid:jonas@mysql.com-20090615070837-9pccutgc7repvb4d) (merge vers: 5.1.35-ndb-6.3.26) (pib:6)

Pushed into 5.1.35-ndb-7.0.7 (revid:jonas@mysql.com-20090615074335-9hcltksp5cu5fucn) (version source revid:jonas@mysql.com-20090615072714-rmfkvrbbipd9r32c) (merge vers: 5.1.35-ndb-7.0.7) (pib:6)

Pushed into 5.1.35-ndb-6.2.19 (revid:jonas@mysql.com-20090615061520-sq7ds4yw299ggugm) (version source revid:jonas@mysql.com-20090615054654-ebgpz7elwu1xj36j) (merge vers: 5.1.35-ndb-6.2.19) (pib:6)

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)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.

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)

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

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)