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
Triage: Triaged: D4 (Minor) / R2 (Low) / E1 (None/Negligible)

[19 Mar 2007 22:22] Axel Schwenke
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.
[2 May 2007 17:26] Heikki Tuuri
Maybe the same bug as http://bugs.mysql.com/bug.php?id=28112
[2 May 2007 17:29] Heikki Tuuri
Marko,

please look at this.

--Heikki
[11 May 2007 12:17] Marko Mäkelä
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.
[11 May 2007 15:19] Heikki Tuuri
Marko,

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

Need to study this more.

Regards,

Heikki
[4 Mar 2008 17:06] Heikki Tuuri
Anyone seen this since May 2007?
--Heikki
[29 Oct 2008 7:40] Marko Mäkelä
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.
[22 Dec 2008 13:09] Marko Mäkelä
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:
[22 Dec 2008 13:53] Heikki Tuuri
Ok to commit the fix.
[8 Apr 2009 19:40] Timothy Smith
Docs team:  This bug is fixed in 6.0.11.  Please return to 'Patch Approved', pending decision on putting it in 5.1.
[8 Apr 2009 23:05] Paul Dubois
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.
[20 Apr 2009 7:28] 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/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
[20 Apr 2009 8:53] 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/72487

3220 Satya B	2009-04-20 [merge]
      NULL MERGE of innodb-5.1-ss3603,BUG#27276 into 6.0 branch
[5 May 2009 19:42] Bugs System
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)
[6 May 2009 14:07] Bugs System
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)
[12 May 2009 1:58] Paul Dubois
Noted in 5.1.35 changelog.
[15 Jun 2009 8:29] Bugs System
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)
[15 Jun 2009 9:08] Bugs System
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)
[15 Jun 2009 9:49] Bugs System
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)
[5 May 2010 15:08] 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)
[6 May 2010 2:58] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug. Re-closing.
[28 May 2010 5:47] 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:17] 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:44] 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)
[29 May 2010 22:57] Paul Dubois
Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.
[15 Jun 2010 8:11] 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:27] 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:48] 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:25] 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:12] 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)