]]>
]]>
 

Bug #55981 Assertion failure in file fsp0fsp.c line 3276
Submitted: 14 Aug 9:07 Modified: 24 Aug 3:27
Reporter: Serge Kozlov Email Updates:
Status: Duplicate
Category:Server: InnoDB Severity:S2 (Serious)
Version:5.6.99-m5 OS:Any
Assigned to: Jimmy Yang Target Version:
Tags: innodb, assertion, fsp0fsp.c, nuts
Triage: Triaged: D1 (Critical)

[14 Aug 9: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 9:12] Serge Kozlov
MTR test case and dump file

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

[23 Aug 10: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 12: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.
[24 Aug 0: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 3:27] Jimmy Yang
Duplicate of bug #55543

 
misc/bug55981.txt · Last modified: 2011/07/17 21:05 (external edit)
Except where otherwise noted, content on this wiki is licensed under the following license:CC Attribution-Noncommercial-Share Alike 3.0 Unported
Contact Us 24 Hours A Day
SupportContact us 24×7
Emergency? Contact us for help now!
Sales North America(888) 316-9775 or
(208) 473-2904
Sales
Europe
+44-208-133-0309 (UK)
0-800-051-8984 (UK)
0-800-181-0665 (GER)
Training(855) 55TRAIN or
(925) 271-5054

 

Share This
]]> ]]>