MySQL Bugs: #46650: Innodb assertion autoinc_lock == lock in lock_table_remove

Bug #46650	Innodb assertion autoinc_lock == lock in lock_table_remove_low on INSERT SELECT
Submitted:	11 Aug 2009 12:51	Modified:	20 Jun 2010 17:33
Reporter:	Philip Stoev	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB Plugin storage engine	Severity:	S1 (Critical)
Version:	5.1,5.4	OS:	Any
Assigned to:	Sunny Bains	CPU Architecture:	Any

Description:
When running a concurrent INSERT SELECT workload on partitioned Innodb tables against the mysql-trunk tree, innodb asserted as follows:

090811 15:46:56  InnoDB: Assertion failure in thread 140138155768144 in file lock/lock0lock.c line 3581
InnoDB: Failing assertion: autoinc_lock == lock
InnoDB: We intentionally generate a memory trap.

# 15:46:58 #5  0x000000315a434a43 in abort () from /lib64/libc.so.6
# 15:46:58 #6  0x000000000086a003 in lock_table_remove_low (lock=0x7f7470000a50) at lock/lock0lock.c:3581
# 15:46:58 #7  0x000000000086a2c6 in lock_table_enqueue_waiting (mode=4, table=0x58f3a80, thr=0x58ec178) at lock/lock0lock.c:3651
# 15:46:58 #8  0x000000000086a4cb in lock_table (flags=0, table=0x58f3a80, mode=LOCK_AUTO_INC, thr=0x58ec178) at lock/lock0lock.c:3754
# 15:46:58 #9  0x000000000089bc23 in row_lock_table_autoinc_for_mysql (prebuilt=0x58eb860) at row/row0mysql.c:938
# 15:46:58 #10 0x0000000000852815 in ha_innobase::innobase_lock_autoinc (this=0x58f0c28) at handler/ha_innodb.cc:4164
# 15:46:58 #11 0x0000000000852875 in ha_innobase::innobase_set_max_autoinc (this=0x58f0c28, auto_inc=12453) at handler/ha_innodb.cc:4215
# 15:46:58 #12 0x000000000085dad7 in ha_innobase::write_row (this=0x58f0c28, record=0x58e5db0 "Щ\002") at handler/ha_innodb.cc:4444
# 15:46:58 #13 0x0000000000767322 in handler::ha_write_row (this=0x58f0c28, buf=0x58e5db0 "Щ\002") at handler.cc:4642
# 15:46:58 #14 0x0000000000775514 in ha_partition::write_row (this=0x58e5ad8, buf=0x58e5db0 "Щ\002") at ha_partition.cc:2997
# 15:46:58 #15 0x0000000000767322 in handler::ha_write_row (this=0x58e5ad8, buf=0x58e5db0 "Щ\002") at handler.cc:4642
# 15:46:58 #16 0x00000000006d2292 in write_record (thd=0x5900d78, table=0x58eff48, info=0x590e530) at sql_insert.cc:1581
# 15:46:58 #17 0x00000000006d26bb in select_insert::send_data (this=0x590e4f0, values=@0x5902d08) at sql_insert.cc:3147
# 15:46:58 #18 0x00000000006a067b in end_send (join=0x7f74700037e8, join_tab=0x590ecc8, end_of_records=false) at sql_select.cc:12000
# 15:46:58 #19 0x00000000006a75a9 in evaluate_join_record (join=0x7f74700037e8, join_tab=0x590ea80, error=0) at sql_select.cc:11260
# 15:46:58 #20 0x00000000006a77f2 in sub_select (join=0x7f74700037e8, join_tab=0x590ea80, end_of_records=false) at sql_select.cc:11151
# 15:46:58 #21 0x00000000006b8d6b in do_select (join=0x7f74700037e8, fields=0x5902d08, table=0x0, procedure=0x0) at sql_select.cc:10901
# 15:46:58 #22 0x00000000006cb140 in JOIN::exec (this=0x7f74700037e8) at sql_select.cc:2202
# 15:46:58 #23 0x00000000006c5f63 in mysql_select (thd=0x5900d78, rref_pointer_array=0x5902dd0, tables=0x590e118, wild_num=0, fields=@0x5902d08, conds=0x0, og_num=0,
# 15:46:58     order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=3489942016, result=0x590e4f0, unit=0x59027d8, select_lex=0x5902c00)
# 15:46:58     at sql_select.cc:2391
# 15:46:58 #24 0x00000000006cb480 in handle_select (thd=0x5900d78, lex=0x5902738, result=0x590e4f0, setup_tables_done_option=1073741824) at sql_select.cc:270
# 15:46:58 #25 0x000000000063ad3c in mysql_execute_command (thd=0x5900d78) at sql_parse.cc:3248
# 15:46:58 #26 0x0000000000640e4c in mysql_parse (thd=0x5900d78,
# 15:46:58     inBuf=0x590d878 "INSERT INTO `table10000_innodb_key_pk_parts_2_int_autoinc` ( `int` ) SELECT X . `pk` FROM `table10000_innodb_int_autoinc` AS X LIMIT 5", length=134, found_semicolon=0x7f7474fe6ee0) at sql_parse.cc:6003
# 15:46:58 #27 0x0000000000641c79 in dispatch_command (command=COM_QUERY, thd=0x5900d78,
# 15:46:58     packet=0x59036c9 "INSERT INTO `table10000_innodb_key_pk_parts_2_int_autoinc` ( `int` ) SELECT X . `pk` FROM `table10000_innodb_int_autoinc` AS X LIMIT 5", packet_length=134) at sql_parse.cc:1222
# 15:46:58 #28 0x000000000064305e in do_command (thd=0x5900d78) at sql_parse.cc:855
# 15:46:58 #29 0x000000000062f8bd in handle_one_connection (arg=0x5900d78) at sql_connect.cc:1131
# 15:46:58 #30 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
# 15:46:58 #31 0x000000315a4e627d in clone () from /lib64/libc.so.6

How to repeat:
ZZ file:

$tables = {
        partitions => [ undef , 'KEY (pk) PARTITIONS 2' ]
};

$fields = {
        types => [ 'int' ],
        indexes => [undef ],
};

$data = {
        numbers => [ 'digit', 'null', undef ],
}

YY file:

query:
        INSERT INTO _table ( _field_no_pk ) SELECT X . _field_key FROM _table AS X LIMIT 5;

RQG command line:

$ perl runall.pl \
  --engine=Innodb \
  --reporters=ErrorLog,Backtrace \
  --mysqld=--loose-innodb-lock-wait-timeout=1 \
  --mysqld=--log-output=none \
  --rows=10000 \
  --queries=1M \
  --duration=600 \
  --basedir=/build/bzr/mysql-trunk \
  --gendata=/path/to/file.zz \
  --grammar=/path/to/file.yy \
  --threads=2

The Random Query Generator can be obtained from

http://launchpad.net/randgen/1.0/1.0/+download/randgen-1.1.zip

Philip - is this one against the InnoDB Plugin + 5.4 server, or the builtin InnoDB in the existing 5.4 tree?

Thanks,
Calvin

Calvin, this is also reproducible against 5.1 with the innodb plugin.

Command line:

$ perl runall.pl \
  --basedir=/build/bzr/bug46650/ \
  --mysqld=--ignore-builtin-innodb \
  --mysqld=--plugin-load=innodb=ha_innodb_plugin.so:innodb_trx=ha_innodb_plugin.so:innodb_locks=ha_innodb_plugin.so:innodb_cmp=ha_innodb_plugin.so:innodb_cmp_reset=ha_innodb_plugin.so:innodb_cmpmem=ha_innodb_plugin.so:innodb_cmpmem_reset=ha_innodb_plugin.so \
  --mysqld=--plugin-dir=/build/bzr/bug46650/storage/innodb_plugin/.libs/ \
  --engine=Innodb \
  --grammar=conf/bug46650.yy \
  --gendata=conf/bug46650.zz

ok. Thanks, Philip!

Sunny, please use the RQG bzr tree from

bzr+ssh://bazaar.launchpad.net/~pstoev/randgen/rqg2

it should allow you to proceed with the test.

Thank you.

Philip,

Thanks for the excellent test case, I was able to reproduce the problem
and fix it. I will be submitting it for internal review but it would be
nice if it can be tested by MySQL in the meantime.

Regards,
-sunny

=== modified file 'storage/innodb_plugin/lock/lock0lock.c'
--- storage/innodb_plugin/lock/lock0lock.c	2009-07-30 12:42:56 +0000
+++ storage/innodb_plugin/lock/lock0lock.c	2009-08-14 11:16:13 +0000
@@ -3574,7 +3574,8 @@
 		and lock_grant()). Therefore it can be empty and we
 		need to check for that. */
 
-		if (!ib_vector_is_empty(trx->autoinc_locks)) {
+		if (!lock_get_wait(lock)
+		    && !ib_vector_is_empty(trx->autoinc_locks)) {
 			lock_t*	autoinc_lock;
 
 			autoinc_lock = ib_vector_pop(trx->autoinc_locks);
@@ -3647,8 +3648,10 @@
 
 	if (lock_deadlock_occurs(lock, trx)) {
 
-		lock_reset_lock_and_trx_wait(lock);
+		/* The order here is important, we don't want to
+		lose the state of the lock before calling remove. */
 		lock_table_remove_low(lock);
+		lock_reset_lock_and_trx_wait(lock);
 
 		return(DB_DEADLOCK);
 	}

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

2873 Alexander Nozdrin	2009-08-24
      Backporting patch for Bug#46650 (Innodb assertion autoinc_lock == lock
      in lock_table_remove_low on INSERT SELECT) to mysql-trunk.

Pushed into mysql-trunk (Azalea release).

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090916063112-8hjmu6wkxfx5qxf4) (version source revid:alik@sun.com-20090916062454-qzqttcefueqgsfn3) (merge vers: 5.4.4-alpha) (pib:11)

Noted in 5.4.4 changelog.

Concurrent INSERT INTO ... SELECT statements for an InnoDB tables
could cause an AUTO_INCREMENT assertion failure.

The 5.4 fix has been pushed to 5.4.2.

Pushed into 5.1.41 (revid:joro@sun.com-20091014143611-cphb0enjlx6lpat1) (version source revid:satya.bn@sun.com-20091008100049-sogaldaljyb21st4) (merge vers: 5.1.40) (pib:13)

Noted in 5.1.41 changelog.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20091022063126-l0qzirh9xyhp0bpc) (version source revid:alik@sun.com-20091019135554-s1pvptt6i750lfhv) (merge vers: 6.0.14-alpha) (pib:13)

Pushed into 5.5.0-beta (revid:alik@sun.com-20091022060553-znkmxm0g0gm6ckvw) (version source revid:alik@sun.com-20091019131022-2o2ymjfjjoraq833) (merge vers: 5.5.0-beta) (pib:13)

Noted in 5.5.0, 6.0.14 changelogs.

Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)

Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)

Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)

Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)

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)

Note bug #58191