Bug #41543 Assertion `m_status == DA_ERROR' failed in Diagnostics_area::sql_errno

• Submitted: 17 Dec 2008 13:20
• Modified: 28 Jan 2009 21:19
• Reporter: Philip Stoev
• Status: Closed
• Category: MySQL Server: Optimizer
• Severity: S1 (Critical)
• Version: 5.1.30,6.0-bzr
• OS: Any
• Assigned to: Georgi Kodinov
• CPU Architecture: Any

[17 Dec 2008 13:20] Philip Stoev

Description:
When executing a concurrent workload involving ROLLBACKS on transaction that cause deadlocks, mysqld asserted as follows:

mysqld: sql_error.h:74: uint Diagnostics_area::sql_errno() const: Assertion `m_status == DA_ERROR' failed.

#6  0x000000315a42bec9 in __assert_fail () from /lib64/libc.so.6
#7  0x00000000006ac048 in Diagnostics_area::sql_errno (this=0x7fb9bcee17d0) at sql_error.h:74
#8  0x000000000080fdc0 in ha_rollback_trans (thd=0x7fb9bcee00a8, all=true) at handler.cc:1293
#9  0x00000000008dc5a9 in trans_rollback (thd=0x7fb9bcee00a8) at transaction.cc:206
#10 0x00000000006d5daa in mysql_execute_command (thd=0x7fb9bcee00a8) at sql_parse.cc:4040
#11 0x00000000006d80c7 in mysql_parse (thd=0x7fb9bcee00a8, inBuf=0x2534800 "ROLLBACK", length=8, found_semicolon=0x7fb9afa2df00) at sql_parse.cc:5735
#12 0x00000000006d8cb2 in dispatch_command (command=COM_QUERY, thd=0x7fb9bcee00a8, packet=0x7fb9bceea979 " ROLLBACK", packet_length=9) at sql_parse.cc:1007
#13 0x00000000006da1db in do_command (thd=0x7fb9bcee00a8) at sql_parse.cc:690
#14 0x00000000006c82f1 in handle_one_connection (arg=0x7fb9bcee00a8) at sql_connect.cc:1145
#15 0x000000315b0073da in start_thread () from /lib64/libpthread.so.0
#16 0x000000315a4e627d in clone () from /lib64/libc.so.6

(gdb) print m_status
$1 = Diagnostics_area::DA_EMPTY

How to repeat:
A test case will be uploaded shortly.

[17 Dec 2008 13:21] Philip Stoev

Test case for bug 41543

Attachment: bug41543.yy (application/octet-stream, text), 735 bytes.

[17 Dec 2008 13:22] Philip Stoev

To reproduce, please branch the Random Query Generator

bzr branch lp:~randgen/randgen/main

and execute:

perl runall.pl \
--basedir=/build/bzr/mysql-6.0/ \
--grammar=conf/bug41543.yy \
--gendata=conf/transactions.zz \
--engine=Innodb

[17 Dec 2008 13:35] Philip Stoev

5.1.30 is also affected. A typical sample of the very simple queries being issued against a very simple table with two integer columns:

                    6 Query     ROLLBACK
                    8 Query     START TRANSACTION
                    8 Query     UPDATE `table10_innodb_int_autoinc` SET `int_key` = `int_key` - 40 , `int` = `int` + 40
                    5 Query     START TRANSACTION
                    7 Query     ROLLBACK
                    6 Query     START TRANSACTION
                    6 Query     INSERT INTO `table10_innodb_int_autoinc` ( `pk` , `int_key` , `int` ) VALUES ( NULL, 70 , 80 )
                    5 Query     UPDATE `table10_innodb_int_autoinc` SET `int_key` = `int_key` - 40 , `int` = `int` + 40 WHERE `pk` > 4 ORDER BY `pk`
                    6 Query     UPDATE `table10_innodb_int_autoinc` SET `int_key` = `int_key` - 80 , `int` = `int` - 70 WHERE `pk` = 7

[17 Dec 2008 13:56] MySQL Verification Team

Thank you for the bug report. Verified as described:

081217 16:51:07 [Note] Event Scheduler: Loaded 0 events
081217 16:51:07 [Note] /home/miguel/bzr/mysql-6.0-build/sql/mysqld: ready for connections.
Version: '6.0.9-alpha-debug-log'  socket: '/home/miguel/bzr/mysql-6.0-build/mysql-test/var/tmp/master.sock'  port: 19306  Source distribution
mysqld: sql_class.h:1192: uint Diagnostics_area::sql_errno() const: Assertion `m_status == DA_ERROR' failed.
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(my_print_stacktrace+0x32)[0xdc24de]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(handle_segfault+0x2a6)[0x73b695]
/lib/libpthread.so.0[0x7fa97d1f00f0]
/lib/libc.so.6(gsignal+0x35)[0x7fa97be8efd5]
/lib/libc.so.6(abort+0x183)[0x7fa97be90b43]
/lib/libc.so.6(__assert_fail+0xe9)[0x7fa97be87d49]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_ZNK16Diagnostics_area9sql_errnoEv+0x34)[0x7280ae]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z17ha_rollback_transP3THDb+0x207)[0x88cde2]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z14trans_rollbackP3THD+0x6f)[0x960b22]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z21mysql_execute_commandP3THD+0x6777)[0x754138]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x273)[0x7562a2]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xa69)[0x756e9f]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(_Z10do_commandP3THD+0x224)[0x758411]
/home/miguel/bzr/mysql-6.0-build/sql/mysqld(handle_one_connection+0x11c)[0x745483]
/lib/libpthread.so.0[0x7fa97d1e83ea]
/lib/libc.so.6(clone+0x6d)[0x7fa97bf42c6d]
081217 16:51:08 - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary

[19 Dec 2008 11:47] Philip Stoev

Table structure and initial contents:

CREATE TABLE `table10_innodb_int_autoinc` (`int_key` int,
pk integer auto_increment,
`int` int,
        key (`int_key` ),
primary key (pk)) ENGINE=innodb ;
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
INSERT IGNORE INTO table10_innodb_int_autoinc VALUES ('100', NULL, '100');
COMMIT;

[19 Dec 2008 17:42] Davi Arnaut

This is probably a optimizer issue. The problem seems to be that the optimizer might ignore a error and accompanied rollback request issued by a storage engine during a table sort. Ignoring the error can lead to wrong (partial) results during a update statement if a row-level lock cannot be granted because of deadlock.

o Server options (*-master.opt)

--innodb_lock_wait_timeout=1 --innodb_rollback_on_timeout=1

o Table and data

create table t1(a integer auto_increment, b int not null, primary key (a)) engine=innodb DEFAULT CHARSET=latin1;
insert into t1 values (NULL,1),(NULL,2),(NULL,3),(NULL,4),(NULL,5),(NULL,6),(NULL,7);

o Wrong results

connection con1;
start transaction;
select * from t1 where b=3 limit 1 for update;
connection con2;
start transaction;
update t1 set b=10 where a > 1 order by a;
select * from t1 where b = 10;

o Assertion

connection con1;
start transaction;
select * from t1 where b=3 limit 1 for update;
connection con2;
start transaction;
update t1 set b=b+12 where a > 2 order by a;
rollback;

o Description

For the above test cases, what happens code wise is that InnoDB encounters a deadlock during the update statement and marks the transaction to rollback (mark_transaction_to_rollback) and returns a error. Since the sort process ignores the returned error (566), a implicit rollback is not issued at the end of the statement because the execution inadvertently succeeds.

o filesort.cc

560│   for (;;)
561│   {
562│     if (quick_select)
563│     {
564│       if ((error= select->quick->get_next()))
565│       {
566├>        error= HA_ERR_END_OF_FILE;
567│         break;
568│       }
569│       file->position(sort_form->record[0]);
570│       DBUG_EXECUTE_IF("debug_filesort", dbug_print_record(sort_form, TRUE););
571│     }

[9 Jan 2009 12:05] 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/62807

2733 Georgi Kodinov	2009-01-09
      Bug #41543: Assertion `m_status == DA_ERROR' failed in Diagnostics_area::sql_errno
      
      No need to mask the error code returned by getting the next row to end of file when
      doing filesort.

[15 Jan 2009 6:33] Bugs System

Pushed into 5.1.31 (revid:[e-mail]-20090115053147-tx1oapthnzgvs1ro) (version source revid:[e-mail]-20090113150631-y84w12o2zmh7j3qd) (merge vers: 5.1.31) (pib:6)

[19 Jan 2009 11:21] Bugs System

Pushed into 5.1.31-ndb-6.2.17 (revid:[e-mail]-20090119095303-uwwvxiibtr38djii) (version source revid:[e-mail]-20090115073240-1wanl85vlvw2she1) (merge vers: 5.1.31-ndb-6.2.17) (pib:6)

[19 Jan 2009 12:59] Bugs System

Pushed into 5.1.31-ndb-6.3.21 (revid:[e-mail]-20090119104956-guxz190n2kh31fxl) (version source revid:[e-mail]-20090119104956-guxz190n2kh31fxl) (merge vers: 5.1.31-ndb-6.3.21) (pib:6)

[19 Jan 2009 16:05] Bugs System

Pushed into 5.1.31-ndb-6.4.1 (revid:[e-mail]-20090119144033-4aylstx5czzz88i5) (version source revid:[e-mail]-20090119144033-4aylstx5czzz88i5) (merge vers: 5.1.31-ndb-6.4.1) (pib:6)

[20 Jan 2009 18:53] Bugs System

Pushed into 6.0.10-alpha (revid:[e-mail]-20090119171328-2hemf2ndc1dxl0et) (version source revid:[e-mail]-20090114143745-x2dvnmix6gjlt6z6) (merge vers: 6.0.10-alpha) (pib:6)

[28 Jan 2009 21:19] Paul DuBois

Noted in 5.1.31, 6.0.10 changelogs.

The optimizer could ignore an error and rollback request during a
filesort, causing an assertion failure.