Bug #67081 Transporting InnoDB tablespaces with a full text index crashes mysqld
Submitted: 4 Oct 2012 13:30 Modified: 16 Oct 2012 23:55
Reporter: Joshua Prunier Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.6.7 OS:Linux (CentOS 6.3)
Assigned to: CPU Architecture:Any
Tags: fulltext, innodb, Tablespace
Triage: Needs Triage: D1 (Critical)

[4 Oct 2012 13:30] Joshua Prunier
Description:
Attempting to transport innodb tablespaces crashes mysqld if the innodb table also has a full text index. The error log output from the table create to crash is below. Transporting innodb tablespaces without a full text index works as advertised.

121004  8:58:08 [Note] InnoDB: Sync to disk of '"jjp"."innodb_ft_test"' started.
121004  8:58:08 [Note] InnoDB: Stopping purge
121004  8:58:08 [Note] InnoDB: Writing table metadata to './jjp/innodb_ft_test.cfg'
121004  8:58:08 [Note] InnoDB: Table '"jjp"."innodb_ft_test"' flushed to disk
121004  8:59:31 [Note] InnoDB: Deleting the meta-data file './jjp/innodb_ft_test.cfg'
121004  8:59:31 [Note] InnoDB: Resuming purge
121004  8:59:52 InnoDB: FTS Optimize Removing table jjp/innodb_ft_test
121004  9:02:15 [Note] InnoDB: Importing tablespace for table 'jjp/innodb_ft_test' that was exported from host 'tarpon.netprospex.com'
121004  9:02:15 [Note] InnoDB: Phase I - Update all pages
121004  9:02:15 [Note] InnoDB: Sync to disk
121004  9:02:15 [Note] InnoDB: Sync to disk - done!
InnoDB: Error: trying to access page number 4294967288 in space 3270,
InnoDB: space name jjp/innodb_ft_test,
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.
121004  9:02:15  InnoDB: Assertion failure in thread 140465044829952 in file fil0fil.cc line 5136
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.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
13:02:15 UTC - 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=10737418240
read_buffer_size=2097152
max_used_connections=3
max_threads=100
thread_count=4
connection_count=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 115549492 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x9ab803d0
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 = 7fc09119ae18 thread_stack 0x80000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x8b47d5]
/usr/sbin/mysqld(handle_fatal_signal+0x401)[0x64b181]
/lib64/libpthread.so.0[0x337c60f500]
/lib64/libc.so.6(gsignal+0x35)[0x337be328a5]
/lib64/libc.so.6(abort+0x175)[0x337be34085]
/usr/sbin/mysqld[0xa52710]
/usr/sbin/mysqld[0xa1f81c]
/usr/sbin/mysqld[0xa1fd2b]
/usr/sbin/mysqld[0xa0db2d]
/usr/sbin/mysqld[0x9e850c]
/usr/sbin/mysqld[0x9803f2]
/usr/sbin/mysqld[0x912720]
/usr/sbin/mysqld(_Z34mysql_discard_or_import_tablespaceP3THDP10TABLE_LISTb+0x9e)[0x70863e]
/usr/sbin/mysqld(_ZN33Sql_cmd_discard_import_tablespace7executeEP3THD+0xef)[0x7f72df]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x2078)[0x6c6db8]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x33d)[0x6c9b7d]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x966)[0x6ca9d6]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x10f)[0x697d8f]
/usr/sbin/mysqld(handle_one_connection+0x45)[0x697e65]
/usr/sbin/mysqld(pfs_spawn_thread+0x13b)[0x8fb8fb]
/lib64/libpthread.so.0[0x337c607851]
/lib64/libc.so.6(clone+0x6d)[0x337bee76dd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fc07400c330): is an invalid pointer
Connection ID (thread ID): 6
Status: 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.
121004 09:02:15 mysqld_safe Number of processes running now: 0
121004 09:02:15 mysqld_safe mysqld restarted
121004  9:02:15 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
121004  9:02:15 [Warning] You need to use --log-bin to make --binlog-format work.
121004  9:02:16 [Note] Plugin 'FEDERATED' is disabled.
121004  9:02:16 [ERROR] Can't open shared library '/usr/lib64/mysql/plugin/ha_sphinx.so' (errno: 0 /usr/lib64/mysql/plugin/ha_sphinx.so: cannot open shared object file: No such file or directory)
121004  9:02:16 [Warning] Couldn't load plugin named 'sphinx' with soname 'ha_sphinx.so'.
121004  9:02:16 InnoDB: The InnoDB memory heap is disabled
121004  9:02:16 InnoDB: Mutexes and rw_locks use GCC atomic builtins
121004  9:02:16 InnoDB: Compressed tables use zlib 1.2.3
121004  9:02:16 InnoDB: Using Linux native AIO
121004  9:02:16 InnoDB: CPU supports crc32 instructions
121004  9:02:16 InnoDB: Initializing buffer pool, size = 90.0G
121004  9:02:21 InnoDB: Completed initialization of buffer pool
121004  9:02:21 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 7332982253557
121004  9:02:21  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 7332982280783
121004  9:02:22  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 34218070, file name /local/mysql/mysql-bin-np.000231
121004  9:02:28 InnoDB: 128 rollback segment(s) are active.
121004  9:02:28 InnoDB: Waiting for the background threads to start
121004  9:02:29 InnoDB: 1.2.7 started; log sequence number 7332982280783
121004  9:02:29 [Note] Server hostname (bind-address): '*'; port: 3306
121004  9:02:29 [Note] IPv6 is available.
121004  9:02:29 [Note]   - '::' resolves to '::';
121004  9:02:29 [Note] Server socket created on IP: '::'.
121004  9:02:29 [Note] Event Scheduler: Loaded 0 events
121004  9:02:29 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.7-rc'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)

How to repeat:
CREATE TABLE innodb_ft_test (
  id int(11) DEFAULT NULL AUTO_INCREMENT,
  title varchar(255) DEFAULT NULL,
  PRIMARY KEY (id),
  FULLTEXT KEY title (title)
) ENGINE=innodb;

insert into innodb_ft_test(title) values('testing...');

flush tables innodb_ft_test with read lock;

... innodb_ft_test.cfg and innodb_ft_test.ibd files copied to the side ...

mysql> alter table innodb_ft_test discard tablespace;
Query OK, 0 rows affected (0.47 sec)

... innodb_ft_test.cfg and innodb_ft_test.ibd files copied back ...

mysql> alter table innodb_ft_test import tablespace;
ERROR 2013 (HY000): Lost connection to MySQL server during query
[12 Oct 2012 19:13] Sveta Smirnova
Thank you for the report.

Verified as described. Backtrace:

Thread 1 (process 12688):
#0  0x0000003429e0b002 in pthread_kill () from /lib64/libpthread.so.0
#1  0x000000000064b1af in handle_fatal_signal (sig=1231603552) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/signal_handler.cc:248
#2  <signal handler called>
#3  0x0000003429230015 in raise () from /lib64/libc.so.6
#4  0x0000003429231980 in abort () from /lib64/libc.so.6
#5  0x0000000000a52710 in fil_io (type=10, sync=<value optimized out>, space_id=6, zip_size=0, block_offset=4294967288, byte_offset=0, len=16384, buf=0x2aaaaf4dc000, 
    message=0x2aaaaf230300) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/fil/fil0fil.cc:5136
#6  0x0000000000a1f81c in buf_read_page_low (err=0x4968d0ac, sync=1, mode=<value optimized out>, space=6, zip_size=0, unzip=<value optimized out>, 
    tablespace_version=9, offset=4294967295) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/buf/buf0rea.cc:192
#7  0x0000000000a1fd2b in buf_read_page (space=6, zip_size=0, offset=4294967295)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/buf/buf0rea.cc:406
#8  0x0000000000a0db2d in buf_page_get_gen (space=6, zip_size=0, offset=4294967295, rw_latch=2, guess=0x0, mode=10, 
    file=0xc105f0 "/pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/btr/btr0btr.cc", line=845, mtr=0x4968d1e0)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/buf/buf0buf.cc:2530
#9  0x00000000009e850c in btr_root_adjust_on_import (index=0x1f636a38) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/include/btr0btr.ic:60
#10 0x00000000009803f2 in row_import_for_mysql (table=0x1f654618, prebuilt=0x1f669d98)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/row/row0import.cc:1864
#11 0x0000000000912720 in ha_innobase::discard_or_import_tablespace (this=0x1f661200, discard=0 '\0')
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/innobase/handler/ha_innodb.cc:9728
#12 0x000000000070863e in mysql_discard_or_import_tablespace (thd=0x1f5228f0, table_list=0x1f6001e0, discard=144)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_table.cc:5283
#13 0x00000000007f72df in Sql_cmd_discard_import_tablespace::execute (this=0x1f600748, thd=0x1f5228f0)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_alter.cc:365
#14 0x00000000006c6db8 in mysql_execute_command (thd=0x1f5228f0) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:4842
#15 0x00000000006c9b7d in mysql_parse (thd=0x1f5228f0, rawbuf=<value optimized out>, length=<value optimized out>, parser_state=<value optimized out>)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:6094
#16 0x00000000006ca9d6 in dispatch_command (command=COM_QUERY, thd=0x1f5228f0, packet=0x1f5fbfd1 "alter table innodb_ft_test import tablespace", packet_length=44)
    at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_parse.cc:1314
#17 0x0000000000697d8f in do_handle_one_connection (thd_arg=<value optimized out>) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_connect.cc:969
#18 0x0000000000697e65 in handle_one_connection (arg=0x1f5228f0) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/sql/sql_connect.cc:885
#19 0x00000000008fb8fb in pfs_spawn_thread (arg=<value optimized out>) at /pb2/build/sb_0-6945253-1348011354.34/mysql-5.6.7-rc/storage/perfschema/pfs.cc:1853
#20 0x0000003429e061b5 in start_thread () from /lib64/libpthread.so.0
#21 0x00000034292cd39d in clone () from /lib64/libc.so.6
#22 0x0000000000000000 in ?? ()

Version 5.7.0 does not crash, since it fails at FLUSH TABLES with a warning: "Warning	1235	InnoDB: This version of MySQL doesn't yet support 'FLUSH TABLES on tables that have an FTS index'"
[16 Oct 2012 23:55] John Russell
Added to changelog for 5.6.8, 5.7.0: 

When using the transportable tablespace feature, the ALTER TABLE ...
IMPORT TABLESPACE statement could crash if the InnoDB table being
flushed contained a FULLTEXT index. With this fix, the table data can
be imported, although you must drop and re-create the FULLTEXT index
after the import operation.