Bug #55981 Assertion failure in file fsp0fsp.c line 3276
Submitted: 14 Aug 2010 7:07 Modified: 24 Aug 2010 1:27
Reporter: Serge Kozlov Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6.99-m5 OS:Any
Assigned to: Assigned Account CPU Architecture:Any
Tags: assertion, fsp0fsp.c, innodb, nuts
Triage: Triaged: D1 (Critical)

[14 Aug 2010 7:07] Serge Kozlov
Description:
MySQL server got assertion in innodb code when performing attached dump file:

Installing MySQL system tables...
OK
Filling help tables...
OK
100814 10:42:03 [Note] Plugin 'FEDERATED' is disabled.
100814 10:42:03 [Note] Plugin 'ndbcluster' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use InnoDB's own implementation
InnoDB: Compressed tables use zlib 1.2.3
InnoDB: The first specified data file ./ibdata1 did not exist:
InnoDB: a new database to be created!
100814 10:42:03  InnoDB: Setting file ./ibdata1 size to 10 MB
InnoDB: Database physically writes the file full: wait...
100814 10:42:03  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
InnoDB: Database physically writes the file full: wait...
100814 10:42:04  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Doublewrite buffer not found: creating new
InnoDB: Doublewrite buffer created
InnoDB: 127 rollback segment(s) active.
InnoDB: Creating foreign key constraint system tables
InnoDB: Foreign key constraint system tables created
100814 10:42:04 InnoDB 1.2.0 started; log sequence number 0
100814 10:42:04 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: 0d1bd0be-a76f-11df-b155-0800272f46ab.
100814 10:42:04 [Note] Event Scheduler: Loaded 0 events
100814 10:42:04 [Note] /home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld: ready for connections.
Version: '5.6.99-m5-log'  socket: '/tmp/socket.1'  port: 10000  Source distribution
100814 10:42:07 [Note] Start binlog_dump to slave_server(2), pos(, 4)
InnoDB: Dump of the tablespace extent descriptor:  len 40; hex 0000000000000000ffffffff0000ffffffff000000000002aaffffffffffffffffffffffffffffff; asc                                         ;
InnoDB: Serious error! InnoDB is trying to free page 4
InnoDB: though it is already marked as free in the tablespace!
InnoDB: The tablespace free space info is corrupt.
InnoDB: You may need to dump your InnoDB tables and recreate the whole
InnoDB: database!
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
100814 10:42:07  InnoDB: Assertion failure in thread 2779286416 in file fsp/fsp0fsp.c line 3276
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.
100814 10:42:07 - mysqld got signal 6 ;
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=8388608
read_buffer_size=131072
max_used_connections=2
max_threads=151
thread_count=2
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337835 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0xaefda88
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 = 0xa5a88398 thread_stack 0x30000
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(my_print_stacktrace+0x39)[0x8601b79]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(handle_segfault+0x39d)[0x82406bd]
[0xef1420]
/lib/libc.so.6(abort+0x101)[0x3c6631]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x852d72a]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x852e108]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x84d2f04]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x84d73a4]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x8537e00]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x8494a91]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x8470d31]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x84b46fe]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x84b4c0d]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld[0x84258bb]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z17ha_rollback_transP3THDb+0xa3)[0x833f873]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z19trans_rollback_stmtP3THD+0x24)[0x83d25c4]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z21mysql_execute_commandP3THD+0x1d0)[0x8254570]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x14d)[0x825c80d]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1525)[0x825dd55]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z10do_commandP3THD+0xc1)[0x825e191]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(_Z24do_handle_one_connectionP3THD+0x704)[0x824d804]
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/sql/.libs/lt-mysqld(handle_one_connection+0x3c)[0x824e03c]
/lib/libpthread.so.0[0x51546b]
/lib/libc.so.6(clone+0x5e)[0x46cdbe]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xaf4d148 = UPDATE t5 SET c_04 = 0, c_02 = '$< OYE8N{q(rAzg+jYN.xxVJ~W_6@[};~oj %61L8+W| 8C|kIlF~J%w[/irb~]m(#L9BR5|/ze w7WJUP{<T:g##<:b&Gq X@%(QOZ_AOozahZf_QVru~3X:!-H9L?1/]Slzk>c#8~NhIC-Z} XIe  <v oks*;hg?kDHTH(LtRD', c_05= '9543-04-21 11:55:56' WHERE c_04 = 0 AND c_02 = '$< OYE8N{q(rAzg+jYN.xxVJ~W_6@[};~oj %61L8+W| 8C|kIlF~J%w[/irb~]m(#L9BR5|/ze w7WJUP{<T:g##<:b&Gq X@%(QOZ_AOozahZf_QVru~3X:!-H9L?1/]Slzk>c#8~NhIC-Z} XIe  <v oks*;hg?kDHTH(LtRD'
thd->thread_id=1
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
/home/ksm/oracle/repo/nuts/var/bin/rep::basic/1/5.6.99-m5/client/.libs/lt-mysqladmin: connect to server at 'localhost' failed
error: 'Can't connect to local MySQL server through socket '/tmp/socket.1' (111)'
Check that mysqld is running and that the socket: '/tmp/socket.1' exists!

How to repeat:
Run attached dump file or try to record attached MTR test case
[14 Aug 2010 7:12] Serge Kozlov
MTR test case and dump file

Attachment: bug_assert_fsp0fsp.tgz (application/x-gzip, text), 1.30 KiB.

[23 Aug 2010 8:08] Jimmy Yang
In essential, a rollback of an update on a table contains BLOB field would deallocate external stored data (space, page) for the BLOB:

Simply the repro to following steps:

mysql> CREATE TABLE t4(c1 int, c2, int, c3 MEDIUMBLOB, PRIMARY KEY(c1)) engine = innodb;

mysql> insert into t4 values(1, 2, REPEAT('b', 54903));
Query OK, 1 row affected (30.91 sec)

mysql> start transaction;

mysql> update t4 set c1 = 3;

mysql> rollback; <=== This rollback removes all external stored BLOB

mysql> start transaction;

mysql> update t4 set c1 = 3;

mysql> rollback; <=== Cannot find the page for external field

(gdb) c
Continuing.
InnoDB: Dump of the tablespace extent descriptor:  len 40; hex 0000000000000000ffffffff0000ffffffff000000000002aaffffffffffffffffffffffffffffff; asc                                         ;
InnoDB: Serious error! InnoDB is trying to free page 4
InnoDB: though it is already marked as free in the tablespace!
InnoDB: The tablespace free space info is corrupt.
InnoDB: You may need to dump your InnoDB tables and recreate the whole
InnoDB: database!
InnoDB: Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
.....

100823  1:03:10  InnoDB: Assertion failure in thread 3000892272 in file /home/jy/work/mysql5.6_1/mysql-next-mr-innodb/storage/innobase/fsp/fsp0fsp.c line 3276

The key for such failure is the deallocation of external stored fields for the original data during the update rollback. More info will be updated.
[23 Aug 2010 10:56] Jimmy Yang
Here is the detail info of the problem.

In short, the external stored blob data is freed in the rollback, while it shouldn't, since the data is inherited from the original row. Such deletion basically delete the original blob data.

The reason it is freed is because the BTR_EXTERN_INHERITED_FLAG  is not set on the field:

In btr_cur_mark_dtuple_inherited_extern(), the status BTR_EXTERN_INHERITED_FLAG is not marked on the field. Thus during rollback when btr_free_externally_stored_field() is called, following condition evaluated to false, and it proceeds to free:

btr_free_externally_stored_field()
{
...
   4572                 if (/* There is no external storage data */
   4573                     page_no == FIL_NULL
   4574                     /* This field does not own the externally stored field */
   4575                     || (mach_read_from_1(field_ref + BTR_EXTERN_LEN)
   4576                         & BTR_EXTERN_OWNER_FLAG)
   4577                     /* Rollback and inherited field */
   4578                     || ((rb_ctx == RB_NORMAL || rb_ctx == RB_RECOVERY)
   4579                         && (mach_read_from_1(field_ref + BTR_EXTERN_LEN)
   4580                             & BTR_EXTERN_INHERITED_FLAG))) {
   4581 
   4582                         /* Do not free */
   4583                         mtr_commit(&mtr);  <==== Should come in here
   4584 
   4585                         return;
   4586                 }

....
}

The reason that BTR_EXTERN_INHERITED_FLAG is not marked because function to mark it (btr_cur_mark_dtuple_inherited_extern() is not called at all:

row_upd_clust_rec_by_insert()
{
        if (node->upd_ext) {   <==== node->upd_ext is NULL
                /* If we return from a lock wait, for example, we may have
                extern fields marked as not-owned in entry (marked in the 
                if-branch above). We must unmark them. */

                btr_cur_unmark_dtuple_extern_fields(entry);

                /* We must mark non-updated extern fields in entry as
                inherited, so that a possible rollback will not free them. */

                btr_cur_mark_dtuple_inherited_extern(entry, node->update); 
        }               
}

So in our case, node->upd_ext is NULL. And  node->upd_ext can be updated in row_upd_replace():

row_upd_replace()
{
	for (col_no = 0; col_no < n_cols; col_no++) {
	       ....
               if (dfield_is_ext(dfield) && col->ord_part) {  <== in our case, col->ord_part is 0
                        ext_cols[n_ext_cols++] = col_no;
                }
	}

        if (n_ext_cols) {
                *ext = row_ext_create(n_ext_cols, ext_cols, row,
                                      dict_table_zip_size(table), heap);
        } else {
                *ext = NULL;
        }
}

8: dfield_is_ext(dfield) = 1
(gdb) p col->ord_part
$106 = 0

As a result node->upd_ext is NULL, btr_cur_mark_dtuple_inherited_extern() is not called to mark BTR_EXTERN_INHERITED_FLAG bit, and during rollback, btr_free_externally_stored_field() frees the external data while it shouldn't.
And if the update/rollback is called again, it would find the external data are already freed.
[23 Aug 2010 22:00] Sunny Bains
Thank you for your bug report. This issue has been committed to our source repository of that product and will be incorporated into the next release.

If necessary, you can access the source repository and build the latest available version, including the bug fix. More information about accessing the source trees is available at

    http://dev.mysql.com/doc/en/installing-source.html
[24 Aug 2010 1:27] Jimmy Yang
Duplicate of bug #55543
[13 Dec 2010 8:22] Marko Mäkelä
I would say that this is a duplicate of Bug #55284, which is Bug #55543 fixed more thoroughly.