MySQL Bugs: #59483: Crash on INSERT/REPLACE in rec_convert_dtuple_to_rec

Bug #59483	Crash on INSERT/REPLACE in rec_convert_dtuple_to_rec_comp with ICP on
Submitted:	13 Jan 2011 19:32	Modified:	10 Feb 2011 23:42
Reporter:	Elena Stepanova	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6.1-m5	OS:	Any
Assigned to:	Marko Mäkelä	CPU Architecture:	Any
Tags:	index_condition_pushdown, optimizer_switch, regression

Description:
(gdb) bt
#0  0x00002b914cf9dea3 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000050bdee in handle_segfault (sig=11) at mysql-5.6.1-m5/sql/mysqld.cc:2511
#2  <signal handler called>
#3  0x00002b914d5bd1a3 in memcpy () from /lib64/libc.so.6
#4  0x000000000137f22e in ?? ()
#5  0x00000000008f943e in rec_convert_dtuple_to_rec_comp (rec=<value optimized out>, extra=<value optimized out>, index=0x1203c98,
    status=<value optimized out>, fields=<value optimized out>, n_fields=7)
    at mysql-5.6.1-m5/storage/innobase/rem/rem0rec.c:1196
#6  0x00000000008fa369 in rec_convert_dtuple_to_rec (buf=<value optimized out>, index=<value optimized out>, dtuple=0x134c178, n_ext=20234832)
    at mysql-5.6.1-m5/storage/innobase/rem/rem0rec.c:1224
#7  0x0000000000854aa2 in btr_cur_optimistic_insert (flags=0, cursor=0x479d3310, entry=0x134c178, rec=0x479d33c8, big_rec=0x479d33c0, n_ext=0,
    thr=0x1362f08, mtr=0x479d2830) at mysql-5.6.1-m5/storage/innobase/include/page0cur.ic:259
#8  0x00000000008fe927 in row_ins_index_entry_low (mode=2, index=0x1203c98, entry=0x134c178, n_ext=0, thr=0x1362f08)
    at mysql-5.6.1-m5/storage/innobase/row/row0ins.c:2107
#9  0x00000000008ff527 in row_ins_step (thr=0x1362f08)
    at mysql-5.6.1-m5/storage/innobase/row/row0ins.c:2188
#10 0x00000000008066b8 in row_insert_for_mysql (mysql_rec=0x1375850 "Ъ", prebuilt=0x12702e8)
    at mysql-5.6.1-m5/storage/innobase/row/row0mysql.c:1201
#11 0x00000000007ed879 in ha_innobase::write_row (this=0x1375590, record=0x1375850 "Ъ")
    at mysql-5.6.1-m5/storage/innobase/handler/ha_innodb.cc:5414
#12 0x0000000000671bd8 in handler::ha_write_row (this=0x1375590, buf=0x1375850 "Ъ")
    at mysql-5.6.1-m5/sql/handler.cc:5854
#13 0x000000000055ea41 in write_record (thd=0x125d8c0, table=0x134fb30, info=0x479d39a0)
    at mysql-5.6.1-m5/sql/sql_insert.cc:1509
#14 0x0000000000565897 in mysql_insert (thd=0x125d8c0, table_list=0x133a5c0, fields=@0x125fe08, values_list=@0x125fe50, update_fields=@0x125fe38,
    update_values=@0x125fe20, duplic=DUP_REPLACE, ignore=false) at mysql-5.6.1-m5/sql/sql_insert.cc:928
#15 0x0000000000575eef in mysql_execute_command (thd=0x125d8c0) at mysql-5.6.1-m5/sql/sql_parse.cc:2845
#16 0x000000000057826a in mysql_parse (thd=0x125d8c0, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=0x479d4df0)
    at mysql-5.6.1-m5/sql/sql_parse.cc:5550
#17 0x0000000000579e07 in dispatch_command (command=COM_QUERY, thd=0x125d8c0, packet=<value optimized out>, packet_length=76)
    at mysql-5.6.1-m5/sql/sql_parse.cc:1078
#18 0x0000000000610417 in do_handle_one_connection (thd_arg=<value optimized out>)
    at mysql-5.6.1-m5/sql/sql_connect.cc:748
#19 0x0000000000610484 in handle_one_connection (arg=<value optimized out>)
    at mysql-5.6.1-m5/sql/sql_connect.cc:684
#20 0x00002b914cf99143 in start_thread () from /lib64/libpthread.so.0
#21 0x00002b914d6088cd in clone () from /lib64/libc.so.6
#22 0x0000000000000000 in ?? ()

got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help diagnose
the problem, but since we have already crashed, something is definitely wrong
and this may fail.

key_buffer_size=4194304
read_buffer_size=131072
max_used_connections=9
max_threads=151
thread_count=9
connection_count=9
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63820 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x125d8c0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 0x479d5160 thread_stack 0x40000
/export/home/tmp/qauser/bin64_561-m5/bin/mysqld(my_print_stacktrace+0x39)[0x7ce8f9]
/export/home/tmp/qauser/bin64_561-m5/bin/mysqld(handle_segfault+0x380)[0x50bdc0]
/lib64/libpthread.so.0[0x2b914cfa0c00]
/lib64/libc.so.6(memcpy+0x143)[0x2b914d5bd1a3]
[0x137f22e]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x133a3f0): REPLACE LOW_PRIORITY INTO `table100_innodb_int_autoinc` (`pk`) VALUES (NULL)
Connection ID (thread ID): 14
Status: NOT_KILLED

How to repeat:
A test case will be provided shortly

Test case:

--source include/have_innodb.inc
--disable_warnings
DROP TABLE IF EXISTS table1, table2;
--enable_warnings

CREATE TABLE table1 (
 i1 int,
 c1 char(12),
 pk integer auto_increment primary key,
 i2 int,
 key (i2)) ENGINE=InnoDB;

INSERT INTO table1 VALUES  
 (4, 'that', NULL, -474021888) ,  
 (1, 'she', NULL, NULL) ,  
 (-2097610752, 'from', NULL, -2114322432) ,  
 (NULL, 'for', NULL, NULL) ,  
 (7, 'o', NULL, NULL) ,  
 (-1583284224, 'the', NULL, 183173120) ,  
 (-850395136, 'i', NULL, NULL) ,  
 (6, 'tell', NULL, 2) ;

CREATE TABLE table2 ( i2 int ) ENGINE=InnoDB;

SELECT * FROM table1 AS t1 WHERE t1.i2 IN (3, 6) LIMIT 2 FOR UPDATE;
INSERT INTO table1 (i2) VALUES (0), (5);

# Cleanup
DROP TABLE table1, table2;
--exit

On a debug version, the same test case causes the following assertion:

InnoDB: Assertion failure in thread 1174985024 in file mysql-5.6.1-m5/storage/innobase/rem/rem0rec.c line 808
InnoDB: Failing assertion: !(col->prtype & 256)

#5  0x00002b8caae9dfb0 in abort () from /lib64/libc.so.6
#6  0x0000000000989593 in rec_get_converted_size_comp_prefix (index=0x156a248, fields=<value optimized out>, n_fields=6, extra=0x0)
    at mysql-5.6.1-m5/storage/innobase/rem/rem0rec.c:808
#7  0x00000000009898b7 in rec_get_converted_size_comp (index=0x156a248, status=<value optimized out>, fields=0x1583860, n_fields=6, extra=0x0)
    at mysql-5.6.1-m5/storage/innobase/rem/rem0rec.c:893
#8  0x00000000008b027c in rec_get_converted_size (index=0x156a248, dtuple=0x1583828, n_ext=0)
    at mysql-5.6.1-m5/storage/innobase/include/rem0rec.ic:1566
#9  0x00000000008b0972 in btr_cur_optimistic_insert (flags=0, cursor=0x4608b190, entry=0x1583828, rec=0x4608b188, big_rec=0x4608b180, n_ext=0,
    thr=0x15af418, mtr=0x4608acb0) at mysql-5.6.1-m5/storage/innobase/btr/btr0cur.c:1216
#10 0x0000000000991044 in row_ins_index_entry_low (mode=2, index=0x156a248, entry=0x1583828, n_ext=0, thr=0x15af418)
    at mysql-5.6.1-m5/storage/innobase/row/row0ins.c:2107
#11 0x0000000000993a0c in row_ins_index_entry (index=0x156a248, entry=0x1583828, n_ext=0, foreign=<value optimized out>, thr=0x15af418)
    at mysql-5.6.1-m5/storage/innobase/row/row0ins.c:2188
#12 0x00000000009945f9 in row_ins_step (thr=0x15af418)
    at mysql-5.6.1-m5/storage/innobase/row/row0ins.c:2273
#13 0x000000000084e098 in row_insert_for_mysql (mysql_rec=0x15ae5b0 "В", prebuilt=0x156d2f8)
    at mysql-5.6.1-m5/storage/innobase/row/row0mysql.c:1201
#14 0x000000000083430b in ha_innobase::write_row (this=0x15ae2f0, record=0x15ae5b0 "В")
    at mysql-5.6.1-m5/storage/innobase/handler/ha_innodb.cc:5414
#15 0x000000000069bed4 in handler::ha_write_row (this=0x15ae2f0, buf=0x15ae5b0 "В")
    at mysql-5.6.1-m5/sql/handler.cc:5854
#16 0x000000000056c263 in write_record (thd=0x15320c0, table=0x15b1310, info=0x4608b8b0)
    at mysql-5.6.1-m5/sql/sql_insert.cc:1734
#17 0x0000000000573d36 in mysql_insert (thd=0x15320c0, table_list=0x157fb78, fields=@0x1534820, values_list=@0x1534868, update_fields=@0x1534850,
    update_values=@0x1534838, duplic=DUP_ERROR, ignore=false) at mysql-5.6.1-m5/sql/sql_insert.cc:928
#18 0x000000000058484b in mysql_execute_command (thd=0x15320c0) at mysql-5.6.1-m5/sql/sql_parse.cc:2845
#19 0x00000000005885c8 in mysql_parse (thd=0x15320c0, rawbuf=0x157fa80 "INSERT INTO table1 (i2) VALUES (0), (5)", length=<value optimized out>,
    parser_state=0x4608cd60) at mysql-5.6.1-m5/sql/sql_parse.cc:5550
#20 0x00000000005894f8 in dispatch_command (command=COM_QUERY, thd=0x15320c0, packet=0x1577a51 "INSERT INTO table1 (i2) VALUES (0), (5)", packet_length=39)
    at mysql-5.6.1-m5/sql/sql_parse.cc:1078
#21 0x000000000058a993 in do_command (thd=0x15320c0) at mysql-5.6.1-m5/sql/sql_parse.cc:815
#22 0x000000000062bd7f in do_handle_one_connection (thd_arg=<value optimized out>)
    at mysql-5.6.1-m5/sql/sql_connect.cc:748
#23 0x000000000062be4a in handle_one_connection (arg=<value optimized out>)
    at mysql-5.6.1-m5/sql/sql_connect.cc:684
#24 0x0000000000a05d1a in pfs_spawn_thread (arg=<value optimized out>)
    at mysql-5.6.1-m5/storage/perfschema/pfs.cc:1360
#25 0x00002b8caa8be143 in start_thread () from /lib64/libpthread.so.0
#26 0x00002b8caaf2d8cd in clone () from /lib64/libc.so.6
#27 0x0000000000000000 in ?? ()

Not reproducible on current 5.5 and 5.1

You were quicker than me. I'm making bug #59474 a duplicate of this.

I believe that this bug is outside the storage engine.

InnoDB gets a value pk=NULL, and the debug assertion correctly notices that the column pk is declared NOT NULL (because PRIMARY KEY implies NOT NULL for every column in the primary key).

I believe that it is the task of MySQL to assign the auto-increment values. It should never pass pk=NULL to the storage engine. The problem must be somewhere in this part of the call stack:

#11 0x084ef565 in ha_innobase::write_row (this=0x8d6ae90, record=0x8d6b050  <incomplete sequence \367>) at /home/marko/innobase/dev/mysql-5.6/storage/innobase/handler/ha_innodb.cc:5427
#12 0x0834aabf in handler::ha_write_row (this=0x8d6ae90, buf=0x8d6b050  <incomplete sequence \367>) at /home/marko/innobase/dev/mysql-5.6/sql/handler.cc:5871
#13 0x081eaac9 in write_record (thd=0x8d67e58, table=0x8d7b7b0, info=0xaf44809c) at /home/marko/innobase/dev/mysql-5.6/sql/sql_insert.cc:1737
#14 0x081e8de1 in mysql_insert (thd=0x8d67e58, table_list=0x8d78ad0, fields=..., values_list=..., update_fields=..., update_values=..., duplic=DUP_ERROR, ignore=false) at /home/marko/innobase/dev/mysql-5.6/sql/sql_insert.cc:931
#15 0x0820044e in mysql_execute_command (thd=0x8d67e58) at /home/marko/innobase/dev/mysql-5.6/sql/sql_parse.cc:2845
#16 0x08207802 in mysql_parse (thd=0x8d67e58, rawbuf=0x8d78a10 "INSERT INTO table1 (i2) VALUES (0), (5)", length=39, parser_state=0xaf449084) at /home/marko/innobase/dev/mysql-5.6/sql/sql_parse.cc:5550
#17 0x081fc447 in dispatch_command (command=COM_QUERY, thd=0x8d67e58, packet=0x8d709e1 "INSERT INTO table1 (i2) VALUES (0), (5)", packet_length=39) at /home/marko/innobase/dev/mysql-5.6/sql/sql_parse.cc:1078

Simplified/reduced version of test case to reproduce crash:

--source include/have_innodb.inc

CREATE TABLE t1 (
 pk INTEGER AUTO_INCREMENT PRIMARY KEY,
 i1 INTEGER,
 c1 CHAR(6),
 i2 INTEGER NOT NULL,
 KEY (i2)
) ENGINE=InnoDB;

INSERT INTO t1 VALUES  
 (NULL, 4, 'that', 8) ,  
 (NULL, 1, 'she', 6) ,  
 (NULL, 6, 'tell', 2) ;

SELECT * FROM t1 WHERE i2 IN (3, 6) LIMIT 2 FOR UPDATE;
INSERT INTO t1 (i2) VALUES (1);

DROP TABLE t1;

This crash might be caused by the
ha_innobase->prebuilt->mysql_template having incorrect entries for the
insert operation. I believe the following happens:

1. First this statement is run:

   SELECT * FROM t1 WHERE i2 IN (3, 6) LIMIT 2 FOR UPDATE;

   This will use ICP and the prebuilt->mysql_template is set up to
   read two of the fields from the index and two of the fields from
   the base record. Since this is a "for update" query the entire
   record will be read and the prebuilt->template_type gets the value
   ROW_MYSQL_WHOLE_ROW.

2. Then the following statement is run:

   INSERT INTO t1 (i2) VALUES (1);

   In ha_innobase::write_row() we have the following code that should
   update the prebuilt->mysql_template if necessary:

	if (prebuilt->mysql_template == NULL
	    || prebuilt->template_type != ROW_MYSQL_WHOLE_ROW) {

		/* Build the template used in converting quickly between
		the two database formats */

		build_template(true);
	}
  
   but since prebuilt->template_type == ROW_MYSQL_WHOLE_ROW already
   the mysql_template will not be updated. This causes the insert
   operation to be executed with a mysql_template set up for reading
   from both the index and the base record (which seems to be wrong).

By always calling build_template() in ha_innobase::write_row() the
mysql_template gets correct values and the crash does no longer happens.

One potential way to fix this is to make the prebuilt->mysql_template "invalid" when at the same time as we clear out the ICP members of the prebuilt. The following patch is one possible fix:

=== modified file 'storage/innobase/handler/ha_innodb.cc'
--- storage/innobase/handler/ha_innodb.cc	2011-01-30 16:56:39 +0000
+++ storage/innobase/handler/ha_innodb.cc	2011-01-31 09:12:21 +0000
@@ -2267,8 +2267,13 @@
 	prebuilt->keep_other_fields_on_keyread = 0;
 	prebuilt->read_just_key = 0;
 	/* Reset index condition pushdown state */
-	prebuilt->idx_cond = NULL;
-	prebuilt->idx_cond_n_cols = 0;
+	if (prebuilt->idx_cond != NULL) {
+	  prebuilt->idx_cond = NULL;
+	  prebuilt->idx_cond_n_cols = 0;
+          /* Make the template invalid to avoid it is re-used. Possibly 
+             introduce a better name for an invalid template const? */
+          prebuilt->template_type = ROW_MYSQL_NO_TEMPLATE;
+	}
 }

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

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

Pushed into mysql-trunk 5.6.2 (revid:vasil.dimov@oracle.com-20110208173442-ocy58fdcuew3xvex) (version source revid:vasil.dimov@oracle.com-20110208173331-fu0j2s14jbg915zu) (merge vers: 5.6.2) (pib:24)