MySQL Bugs: #57799: READ UNCOMMITTED access failure of off-page DYNAMIC or COMPRESSED columns again

Bug #57799	READ UNCOMMITTED access failure of off-page DYNAMIC or COMPRESSED columns again
Submitted:	28 Oct 2010 10:36	Modified:	10 Dec 2010 3:42
Reporter:	Marko Mäkelä	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	5.1 plugin, 5.5+	OS:	Any
Assigned to:	Marko Mäkelä	CPU Architecture:	Any
Tags:	BLOB, compressed, dynamic, innodb, read uncommitted

Description:
This is follow-up to Bug #54358. Not all occurrences of the bug were fixed.

InnoDB: Failing assertion: memcmp(data, field_ref_zero, BTR_EXTERN_FIELD_REF_SIZE)

 #5  0x0000003acbc31d10 in abort () from /lib64/libc.so.6
 #6  0x00000000008b8e6c in btr_copy_externally_stored_field_prefix ()
 #7  0x0000000000874965 in row_sel_sec_rec_is_for_blob ()

How to repeat:
Run a stress test that involves frequently killing and restarting the server while it is under load. This bug has a low reproducibility.

Suggested fix:
Check all calls to btr_copy_externally_stored_field_prefix_low() and do the right thing when the BLOB pointer is null (full of zero bytes)

I'd like to blame the failure below on this bug, it also happens with
read uncommitted. After that the recovery fails because the rollback 
keeps asserting
on double free.

[n:c55b] ima@dscczz02.us.oracle.com$ n exp keep.incident_c55b.1.double.free -q

 mysql-5.5-innodb,  r3201, tests r1220, srcover.sh kbs 16 --times 11 --seconds 30 --increment 5
bzr revision-id: kevin.lewis@oracle.com-20101026191831-1zm2j4vs0gchqxq0

server log: dscczz02:/spare2/mizioumt/ctc/keep.incident_c55b.1.double.free/log/c55b/mysqld_c55b_28228_step1.log

101026 13:14:33  InnoDB: Assertion failure in thread 1296984384 in file /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/fsp/fsp0fsp.c line 3276
101026 13:14:33 - mysqld got signal 6 ;

dscczz02:/spare2/mizioumt/ctc/keep.incident_c55b.1.double.free/data/c55b/core.28228

extracting stack backtrace for core.28228...
 Thread 1 (Thread 28309):
 #0  0x0000003acc80bd02 in pthread_kill () from /lib64/libpthread.so.0
 #1  0x00000000009f3427 in my_write_core (sig=6)
     at /spare2/mizioumt/ctc/mysql_src_c55b/mysys/stacktrace.c:328
 #2  0x000000000053786f in handle_segfault (sig=6)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/mysqld.cc:2511
 #3  <signal handler called>
 #4  0x0000003acbc30265 in raise () from /lib64/libc.so.6
 #5  0x0000003acbc31d10 in abort () from /lib64/libc.so.6
 #6  0x00000000008f965a in fseg_free_page_low (seg_inode=0x2aaac64dc0f2 "",
     space=6, zip_size=2048, page=38, mtr=0x4d4e3620)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/fsp/fsp0fsp.c:3276
 #7  0x00000000008f9987 in fseg_free_page (seg_header=0x2aaac64e004a "",
     space=6, page=38, mtr=0x4d4e3620)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/fsp/fsp0fsp.c:3386
 #8  0x00000000008a9ee7 in btr_page_free_low (index=0x1d07f2e8,
     block=0x2aaac6407ae0, level=0, mtr=0x4d4e3620)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/btr/btr0btr.c:508
 #9  0x00000000008bbd40 in btr_free_externally_stored_field (index=0x1d07f2e8,
     field_ref=0x2aaac64e0108 "", rec=0x2aaac64e00d5 "khE5BLlGpa\200",
     offsets=0x2aaaf80016d8, page_zip=0x2aaac6405630, i=6, rb_ctx=RB_NORMAL,
     local_mtr=0x4d4e3c70)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/btr/btr0cur.c:4615
 #10 0x00000000008bbfdc in btr_rec_free_externally_stored_fields (
     index=0x1d07f2e8, rec=0x2aaac64e00d5 "khE5BLlGpa\200",
     offsets=0x2aaaf80016d8, page_zip=0x2aaac6405630, rb_ctx=RB_NORMAL,
     mtr=0x4d4e3c70)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/btr/btr0cur.c:4700
 #11 0x00000000008b91ad in btr_cur_pessimistic_delete (err=0x4d4e4110,
     has_reserved_extents=0, cursor=0x1d3bfe00, rb_ctx=RB_NORMAL,
     mtr=0x4d4e3c70)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/btr/btr0cur.c:3055
 #12 0x000000000095555d in row_undo_ins_remove_clust_rec (node=0x1d3bfd88)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/row/row0uins.c:117
 #13 0x0000000000955d00 in row_undo_ins (node=0x1d3bfd88)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/row/row0uins.c:362
 #14 0x000000000094f4f6 in row_undo (node=0x1d3bfd88, thr=0x1d498bb0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/row/row0undo.c:320
 #15 0x000000000094f9ab in row_undo_step (thr=0x1d498bb0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/row/row0undo.c:367
 #16 0x0000000000941e48 in que_thr_step (thr=0x1d498bb0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/que/que0que.c:1245
 #17 0x0000000000941abc in que_run_threads_low (thr=0x1d498bb0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/que/que0que.c:1305
 #18 0x0000000000942255 in que_run_threads (thr=0x1d498980)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/que/que0que.c:1342
 #19 0x0000000000896cd2 in trx_general_rollback_for_mysql (trx=0x1d147738,
     savept=0x0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/trx/trx0roll.c:97
 #20 0x0000000000897187 in trx_rollback_for_mysql (trx=0x1d147738)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/trx/trx0roll.c:146
 #21 0x0000000000858574 in innobase_rollback (hton=0x1a2a9960, thd=0x1d240be0,
     all=true)
     at /spare2/mizioumt/ctc/mysql_src_c55b/storage/innobase/handler/ha_innodb.cc:2815
 #22 0x00000000006fe5e0 in ha_rollback_trans (thd=0x1d240be0, all=true)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/handler.cc:1354
 #23 0x000000000068971c in trans_rollback (thd=0x1d240be0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/transaction.cc:232
 #24 0x00000000005bdb8c in mysql_execute_command (thd=0x1d240be0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_parse.cc:3675
 #25 0x00000000005bf9aa in mysql_parse (thd=0x1d240be0,
     rawbuf=0x1d352580 "rollback", length=8, parser_state=0x4d4e5a10)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_parse.cc:5499
 #26 0x00000000005c09a6 in dispatch_command (command=COM_QUERY, thd=0x1d240be0,
     packet=0x1d398391 "rollback", packet_length=8)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_parse.cc:1029
 #27 0x00000000005c1b8d in do_command (thd=0x1d240be0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_parse.cc:769
 #28 0x000000000067ad1d in do_handle_one_connection (thd_arg=0x1d240be0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_connect.cc:745
 #29 0x000000000067ae19 in handle_one_connection (arg=0x1d240be0)
     at /spare2/mizioumt/ctc/mysql_src_c55b/sql/sql_connect.cc:684
 #30 0x0000003acc80673d in start_thread () from /lib64/libpthread.so.0
 #31 0x0000003acbcd3d1d in clone () from /lib64/libc.so.6

The failure reported on [28 Oct 18:22] looks like Bug #55284 to me.

As far as I can tell, only the call to btr_copy_externally_stored_field_prefix() in row_sel_sec_rec_is_for_blob() needs to be changed. The calls in row_upd_ext_fetch() and trx_undo_page_fetch_ext() must expect that the off-page column exists. Update and rollback are locking operations, and they are never performed in the READ UNCOMMITTED mode.

For fetching complete off-page columns, the function btr_rec_copy_externally_stored_field() already checks if the pointer is null (all-zero). Two of its callers (row_merge_copy_blobs() and row_sel_fetch_columns()) rightfully assert that the fetch succeeded, and the third one (row_sel_store_mysql_rec(), the only one that can be executed as READ UNCOMMITTED) does the right thing.

Attaching the patch here, because email does not work at the moment. The fix is for InnoDB Plugin and later. The built-in InnoDB in MySQL 5.1 is not affected, because it does not support the ROW_FORMATs DYNAMIC or COMPRESSED.

=== modified file 'storage/innodb_plugin/row/row0sel.c'
--- storage/innodb_plugin/row/row0sel.c	revid:marko.makela@oracle.com-20101019060415-bj3u6ewk022mk4nr
+++ storage/innodb_plugin/row/row0sel.c	2010-11-01 13:10:07 +0000
@@ -106,6 +106,18 @@ row_sel_sec_rec_is_for_blob(
 	ulint	len;
 	byte	buf[DICT_MAX_INDEX_COL_LEN];
 
+	ut_a(clust_len >= BTR_EXTERN_FIELD_REF_SIZE);
+
+	if (UNIV_UNLIKELY
+	    (!memcmp(clust_field + clust_len - BTR_EXTERN_FIELD_REF_SIZE,
+		     field_ref_zero, BTR_EXTERN_FIELD_REF_SIZE))) {
+		/* The externally stored field was not written yet.
+		This record should only be seen by
+		recv_recovery_rollback_active() or any
+		TRX_ISO_READ_UNCOMMITTED transactions. */
+		return(FALSE);
+	}
+
 	len = btr_copy_externally_stored_field_prefix(buf, sizeof buf,
 						      zip_size,
 						      clust_field, clust_len);

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

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

Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (version source revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (merge vers: 5.6.1) (pib:23)

Pushed into mysql-5.1 5.1.55 (revid:sunanda.menon@oracle.com-20101215054055-vgwki317xg1wphhh) (version source revid:sunanda.menon@oracle.com-20101215054055-vgwki317xg1wphhh) (merge vers: 5.1.55) (pib:23)

Pushed into mysql-5.5 5.5.9 (revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (version source revid:jonathan.perkin@oracle.com-20101216101358-fyzr1epq95a3yett) (merge vers: 5.5.9) (pib:24)