Bug #55543 InnoDB Plugin: Signal 6: Assertion failure in file fil/fil0fil.c line 4306
Submitted: 26 Jul 2010 2:58 Modified: 27 Jan 2011 19:13
Reporter: Roel Van de Paar (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB Plugin storage engine Severity:S1 (Critical)
Version:5.1.49, 5.5, 5.5.6rc OS:Linux
Assigned to: Sunny Bains CPU Architecture:Any
Triage: Triaged: D1 (Critical) / R3 (Medium) / E3 (Medium)

[26 Jul 2010 2:58] Roel Van de Paar
Description:
This crash was produced inside a VM (Ubuntu 9.04, 32bit, VBox 3.2.6)
==============
InnoDB: Error: trying to access page number 805829503 in space 0,
InnoDB: space name ./ibdata1,
InnoDB: which is outside the tablespace bounds.
InnoDB: Byte offset 0, len 16384, i/o type 10.
InnoDB: If you get this error at mysqld startup, please check that
InnoDB: your my.cnf matches the ibdata files that you have in the
InnoDB: MySQL server.
100726  5:49:31  InnoDB: Assertion failure in thread 2814622608 in file fil/fil0fil.c line 4306
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
100726  5:49:31 - mysqld got signal 6 ;
==============

How to repeat:
==============
roel@roel-ubuntu-vm:/randgen/new_testing/5$ cat 5
cd /randgen/randgen
rm -R /tmp/51/
rm -R /tmp/52/
rm ./51.log
rm ./52.log
perl ./runall.pl \
  --basedir=/mysql/mysql-5.1.49-linux-i686-glibc23/ \
  --vardir1=/tmp/51/ \
  --vardir2=/tmp/52/ \
  --mysqld1=--log-output=none \
  --mysqld1=--log_error=/randgen/new_testing/5/51.log \
  --mysqld2=--log-output=none \
  --mysqld2=--log_error=/randgen/new_testing/5/52.log \
  --mysqld2=--ignore-builtin-innodb \
  --mysqld2=--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 \
  --mysqld2=--plugin-dir=/mysql/mysql-5.1.49-linux-i686-glibc23/lib/plugin/ \
  --gendata=/randgen/new_testing/5/5.zz \
  --grammar=/randgen/new_testing/5/5.yy \
  --queries=100000 \
  --threads=10 \
  --Validators=ResultsetComparator,MarkErrorLog,AbortOnSyntaxError 
cd /randgen/new_testing/5/

roel@roel-ubuntu-vm:/randgen/new_testing/5$ cat 5.zz
$tables = {
        rows => [100],
        engines => ['InnoDB'],
        pk => ['int auto_increment']
};

$fields = {
        types => ['set','blob']
};

$data = {
        blobs => ['english','data']
};

roel@roel-ubuntu-vm:/randgen/new_testing/5$ cat 5.yy
query:
 	update | insert | delete ;

update:
 	UPDATE _table SET _field = digit WHERE condition ;

delete:
	DELETE FROM _table WHERE condition ;

insert:
	INSERT INTO _table ( _field ) VALUES ( _digit ) ;

condition:
	_field > value AND _field < value ;

value:
	_digit | _char(255) | _english | _datetime | NULL ;
==============

Run the above for some time. If you don't get a crash in the first 5-10 minutes, stop it (CTRL-C), and re-start. It crashed for me 3 times out of about 6-10 tries.
[26 Jul 2010 3:14] Roel Van de Paar
Verifying based on the fact that I have been able to reproduce it several times, and also this: bug #49893
[26 Jul 2010 4:23] Roel Van de Paar


Attachment: crash1.txt (text/plain), 6.45 KiB.

[26 Jul 2010 4:24] Roel Van de Paar


Attachment: crash2.txt (text/plain), 81.50 KiB.

[26 Jul 2010 4:24] Roel Van de Paar
Files needed to reproduce

Attachment: crash3.txt (text/plain), 28.68 KiB.

[26 Jul 2010 4:25] Roel Van de Paar
s/Files needed to reproduce//
[26 Jul 2010 4:26] Roel Van de Paar
See bug #55542
[26 Jul 2010 7:08] Calvin Sun
Likely caused by the mismatch of data files and log files.

Which data files mysqld1 uses? which ones mysqld2 uses?
[26 Jul 2010 10:01] Roel Van de Paar
No, this is not the case: I was able to reproduce this using a clean setup: no running mysqld's, directories deleted (see start of script above: rm -R /tmp/51/ and rm -R /tmp/52/) and then start script. Had to try a few times (~3-5) to get it to crash, but then it did:

=============
roel@roel-ubuntu-vm:/randgen/new_testing/5$ kill -9 `pidof mysqld`
roel@roel-ubuntu-vm:/randgen/new_testing/5$ ps -A | grep -v grep | grep mysqld
roel@roel-ubuntu-vm:/randgen/new_testing/5$ ./5 > 5out2.txt
rm: cannot remove `./51.log': No such file or directory
rm: cannot remove `./52.log': No such file or directory
"/randgen/randgen/" is not a core dump: Is a directory
No stack.
/randgen/randgen/backtrace.gdb:20: Error in sourced command file:
No registers.
"/randgen/randgen/" is not a core dump: Is a directory
/randgen/randgen/backtrace-all.gdb:19: Error in sourced command file:
No registers.

warning: Can't read pathname for load map: Input/output error.
4319	mysqld.cc: No such file or directory.

warning: Can't read pathname for load map: Input/output error.
roel@roel-ubuntu-vm:/randgen/new_testing/5$ ls -l /tmp/51/master-data/
total 28688
-rw-rw---- 1 roel roel 18874368 2010-07-26 19:35 ibdata1
-rw-rw---- 1 roel roel  5242880 2010-07-26 19:35 ib_logfile0
-rw-rw---- 1 roel roel  5242880 2010-07-26 19:35 ib_logfile1
-rw-rw---- 1 roel roel     5349 2010-07-26 19:36 innodb_status.21149
drwxr-xr-x 2 roel roel     4096 2010-07-26 19:35 mysql
drwxr-xr-x 2 roel roel     4096 2010-07-26 19:35 test
roel@roel-ubuntu-vm:/randgen/new_testing/5$ ls -l /tmp/52/master-data/
total 59388
-rw------- 1 roel roel 281481216 2010-07-26 19:35 core
-rw-rw---- 1 roel roel  18874368 2010-07-26 19:35 ibdata1
-rw-rw---- 1 roel roel   5242880 2010-07-26 19:35 ib_logfile0
-rw-rw---- 1 roel roel   5242880 2010-07-26 19:35 ib_logfile1
-rw-rw---- 1 roel roel         0 2010-07-26 19:35 innodb_status.21177
drwxr-xr-x 2 roel roel      4096 2010-07-26 19:35 mysql
drwxr-xr-x 2 roel roel      4096 2010-07-26 19:35 test
roel@roel-ubuntu-vm:/randgen/new_testing/5$ ps -A | grep -v grep | grep mysqld
21149 pts/1    00:00:01 mysqld   <---- Only one mysqld running, the other one crashed.
=============
[26 Jul 2010 10:04] Roel Van de Paar
This was using  --queries=5000 --threads=10

Attachment: 5out2.txt (text/plain), 97.97 KiB.

[26 Jul 2010 10:09] Shane Bester
so, purge thread crashes in the background.  its confusing why this testcase needs two instances of mysqld?
[26 Jul 2010 10:18] Roel Van de Paar
Core file from earlier crash

Attachment: core_bug_55543_1.tar.gz (application/x-gzip, text), 281.75 KiB.

[26 Jul 2010 15:05] Calvin Sun
Thanks for the additional info. Please try with only one instance of mysqld. Also, where we can get the randgen you are using?
[26 Jul 2010 15:15] Valeriy Kravchuk
Random query generator is available at https://launchpad.net/randgen. See http://forge.mysql.com/wiki/RQG also.
[27 Jul 2010 1:01] Roel Van de Paar
Only took one attempt to get it to crash with one server.
============== 
roel@roel-ubuntu-vm:/randgen/new_testing/5$ cat 5
kill -9 `pidof mysqld`
cd /randgen/randgen
rm -R /tmp/bug55543/
rm ./bug55543.log
perl ./runall.pl \
  --basedir=/mysql/mysql-5.1.49-linux-i686-glibc23/ \
  --vardir=/tmp/bug55543/ \
  --mysqld=--log-output=none \
  --mysqld=--log_error=/randgen/new_testing/5/bug55543.log \
  --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=/mysql/mysql-5.1.49-linux-i686-glibc23/lib/plugin/ \
  --gendata=/randgen/new_testing/5/5.zz \
  --grammar=/randgen/new_testing/5/5.yy \
  --queries=5000 \
  --threads=10 \
  --Validators=ResultsetComparator,MarkErrorLog,AbortOnSyntaxError 
cd /randgen/new_testing/5/
==============
[27 Jul 2010 1:04] Roel Van de Paar
Log of one server only crash

Attachment: bug55543_1.log (application/octet-stream, text), 6.26 KiB.

[27 Jul 2010 1:05] Roel Van de Paar


Attachment: screencapture_bug_55543_single_server_only.txt (text/plain), 37.75 KiB.

[27 Jul 2010 1:06] Roel Van de Paar
(All testing for this bug was done using latest bzr pull of randgen)
[3 Aug 2010 10:48] Marko Mäkelä
Bug #55284 is a possible duplicate of this.
[3 Aug 2010 12:03] Marko Mäkelä
Sorry, it could have been a wrong alert about the BLOB leak. I ran this under gdb:

CREATE TABLE t(a INT PRIMARY KEY,b TEXT)ENGINE=InnoDB;
INSERT INTO t VALUES(1,repeat('a',12345)),(2,'b');
UPDATE t SET a=2;
DELETE FROM t;

The UPDATE statement will fail because of a duplicate key. (A foreign key constraint violation or a lock wait timeout could do as well.)

I wrongly assumed that the externally stored column b of the record (1,repeat('a',12345)) should be marked "not owned", and it will not be freed by purge. It is marked "owned" again by this code:

#0  mlog_write_ulint (ptr=0xb6a246e3 "", val=<value optimized out>, type=1 '\001', mtr=0xb1e8717c) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/mtr/mtr0log.c:270
#1  0x083dbcd1 in btr_cur_unmark_extern_fields (page_zip=<value optimized out>, rec=<value optimized out>, index=0x89f4088, offsets=0xb1e86e78, mtr=0xb1e8717c) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/btr/btr0cur.c:3730
#2  0x083e4192 in btr_cur_update_in_place (flags=<value optimized out>, cursor=0x89f67ec, update=0x89f6968, cmpl_info=0, thr=0x89f6738, mtr=0xb1e8717c) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/btr/btr0cur.c:1915
#3  0x083e46be in btr_cur_optimistic_update (flags=7, cursor=0x89f67ec, update=0x89f6968, cmpl_info=0, thr=0x89f6738, mtr=0xb1e8717c) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/btr/btr0cur.c:1996
#4  0x08474024 in row_undo_mod_clust_low (node=0x89f6798, thr=0x0, mtr=0xb6a246e3, mode=2) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0umod.c:128
#5  0x08474aa5 in row_undo_mod_clust (node=0x89f6798, thr=<value optimized out>) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0umod.c:258
#6  0x084752c3 in row_undo_mod (node=0x89f6798, thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0umod.c:888
#7  0x0846f8c6 in row_undo (thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0undo.c:325
#8  row_undo_step (thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0undo.c:367
#9  0x08465d0d in que_thr_step (thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/que/que0que.c:1245
#10 que_run_threads_low (thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/que/que0que.c:1310
#11 que_run_threads (thr=0x89f6738) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/que/que0que.c:1347
#12 0x083c2a81 in trx_general_rollback_for_mysql (trx=0x89e3100, savept=0xb1e87854) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/trx/trx0roll.c:97
#13 0x08398877 in row_mysql_handle_errors (new_err=0xb1e8785c, trx=0x89e3100, thr=0x89f4568, savept=0xb1e87854) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0mysql.c:589
#14 0x08398c3e in row_update_for_mysql (mysql_rec=0x89f2ee0 "\376\001", prebuilt=0x89f3190) at /home/marko/innobase/dev/mysql-5.5/storage/innobase/row/row0mysql.c:1459

I seem to remember that a lock wait timeout does not always result in a transaction rollback, depending on configuration options. We should review that.
[3 Aug 2010 12:59] Marko Mäkelä
I checked the lock wait timeout case, and btr_free_externally_stored_field() was invoked by the master thread in order to free the BLOB after the DELETE statement.

Thus, Sunny's fix is complete, and my concern is invalid. For the record, here is my test case, ran with both --innodb-rollback-on-timeout=0 and --innodb-rollback-on-timeout=1:

-- source include/have_innodb.inc

CREATE TABLE t(a INT PRIMARY KEY,b TEXT)ENGINE=InnoDB;
INSERT INTO t VALUES(1,repeat('a',12345)),(2,'b');

-- connect (con1,localhost,root,,)

-- connection con1

BEGIN;
UPDATE t SET b=NULL WHERE a=2;

-- connection default
SET SESSION innodb_lock_wait_timeout=1;
-- error ER_LOCK_WAIT_TIMEOUT
UPDATE t SET a=2;
-- connection con1

DELETE FROM t;
COMMIT;
-- disconnect con1
-- connection default
DROP TABLE t;
[23 Aug 2010 11:30] Marko Mäkelä
Bug #55981 could be related to this.b
[25 Aug 2010 8:38] Marko Mäkelä
Bug #56173 is another duplicate of this.
[28 Sep 2010 8:47] Bugs System
Pushed into mysql-5.1 5.1.52 (revid:sunanda.menon@sun.com-20100928083322-wangbv97uobu7g66) (version source revid:sunanda.menon@sun.com-20100928083322-wangbv97uobu7g66) (merge vers: 5.1.52) (pib:21)
[14 Oct 2010 8:26] Bugs System
Pushed into mysql-5.1-telco-7.0 5.1.51-ndb-7.0.20 (revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (version source revid:martin.skold@mysql.com-20101014082627-jrmy9xbfbtrebw3c) (merge vers: 5.1.51-ndb-7.0.20) (pib:21)
[14 Oct 2010 8:41] Bugs System
Pushed into mysql-5.1-telco-6.3 5.1.51-ndb-6.3.39 (revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (version source revid:martin.skold@mysql.com-20101014083757-5qo48b86d69zjvzj) (merge vers: 5.1.51-ndb-6.3.39) (pib:21)
[14 Oct 2010 8:56] Bugs System
Pushed into mysql-5.1-telco-6.2 5.1.51-ndb-6.2.19 (revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (version source revid:martin.skold@mysql.com-20101014084420-y54ecj85j5we27oa) (merge vers: 5.1.51-ndb-6.2.19) (pib:21)
[1 Nov 2010 11:30] Marko Mäkelä
I believe that a more complete fix is needed in order to counter Bug #55248.
[2 Nov 2010 13:20] Marko Mäkelä
Note: this bug was not fixed in the built-in InnoDB of MySQL 5.1. The fix is only in the InnoDB Plugin of MySQL 5.1, and in MySQL 5.5 and later. I think that Bug #55284 (a superset of this bug) can be fixed in the built-in InnoDB of MySQL 5.1. The bug exists in all MySQL/InnoDB versions, starting with 3.23.53.
[9 Nov 2010 19:46] Bugs System
Pushed into mysql-5.5 5.5.7-rc (revid:sunanda.menon@sun.com-20101109182959-otkxq8vo2dcd13la) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)
[12 Nov 2010 4:26] Roel Van de Paar
Confirmed not-reproducible in 5.5.7rc (reproducible, easily, in 5.5.6rc)
[13 Nov 2010 16:10] Bugs System
Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (merge vers: 5.1.50) (pib:21)
[13 Nov 2010 16:35] Bugs System
Pushed into mysql-next-mr (revid:alexander.nozdrin@oracle.com-20101113160336-atmtmfb3mzm4pz4i) (version source revid:marko.makela@oracle.com-20100824081003-v4ecy0tga99cpxw2) (pib:21)
[1 Dec 2010 7:07] Marko Mäkelä
I would say that this is a subset of Bug #55284, or that the committed fix of Bug #55284 is incomplete. The full fix will be in Bug #55284.

Also, note that the Bug #55543 fix was was not committed to the built-in InnoDB in MySQL 5.1; only to the InnoDB Plugin in 5.1, and to MySQL 5.5 and later.
[1 Dec 2010 7:10] Marko Mäkelä
Sorry, I meant that the committed fix of Bug #55543 is incomplete. The fix of Bug #55284 has not been committed yet.
[27 Jan 2011 19:13] John Russell
Added to changelog for 5.5.7 and 5.1.51:

The server could crash with an assertion, possibly leading to data
corruption, while updating the primary key of an InnoDB table
containing BLOB or other columns requiring off-page storage. This fix
applies to the InnoDB Plugin in MySQL 5.1, and to InnoDB 1.1 in MySQL
5.5.