Combination of CREATE, RENAME, and ALTER TABLE statements on related tables causes crash

[Richard Heelin]

Recently set up a new database server with percona-server-server-5.6 version 5.6.20. After installing the database I ran our migration scripts to configure the database, which failed part way through saying it had lost connection to the database.

After some investigation we found that percona was crashing during the migration due to one of the alter table statements, generating the attached stacktrace.

Trying the same process against the previous release, 5.6.19, worked as expected with the migration script completing and the server remaining available.

Attempted to create a simple example of what the migration script was doing but the bug seems to vary based on how many tables are needed to be created renamed / altered before the server will crash. Wrapping the rename or alteration in a transaction seems to increase the likelihood of the server crashing. It is still possible to crash the server without transactions but not as reliably, sometimes requiring the example to be run multiple times in quick succession before the server would crash.

The bug is definitely related to related tables (with foreign keys) been renamed and their related columns being renamed, as doing one without the other does not result in a crash, however many times you try in quick succession.

Attached is a script that will generate some tables that relate to a further table, and then attempt to rename the base table followed by renaming the related columns in the other tables. After some playing around I was able to get the server to reliably crash with 20 related tables, with it sometimes crashing with as low as 11 related tables. This is against a fresh install of percona-server-server-5.6 version 5.6.20 with no modification to config.

[Valerii Kravchuk (valerii-kravchuk)]

I was able to reproduce exactly the same crash on Percona Server 5.6.20 by setting tables to 20 in your script and running it with bash. More details to follow soon.

[Valerii Kravchuk (valerii-kravchuk)]

This is what I see in the error log:

2014-09-05 18:39:48 29660 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.20-68.0' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Percona Server (GPL), Release 68.0, Revision 656
15:45:39 UTC - mysqld got signal 11 ;
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 69178 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x336b720
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 = 7f85a6cb3e60 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2c)[0x903efc]
/usr/sbin/mysqld(handle_fatal_signal+0x352)[0x660b02]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f85d479f340]
/lib/x86_64-linux-gnu/libc.so.6(+0x140d5a)[0x7f85d3effd5a]
/usr/sbin/mysqld(_ZNSt8_Rb_treeIP14dict_foreign_tS1_St9_IdentityIS1_E20dict_foreign_compareSaIS1_EE11equal_rangeERKS1_+0x9d)[0xb00c0d]
/usr/sbin/mysqld[0xb0063a]
/usr/sbin/mysqld[0x9c319a]
/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderb+0x1f81)[0x7456e1]
/usr/sbin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x482)[0x839c42]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1509)[0x6ed1d9]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x5c8)[0x6f2ed8]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x21f6)[0x6f5716]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0x20d)[0x6bb4bd]
/usr/sbin/mysqld(handle_one_connection+0x39)[0x6bb539]
/usr/sbin/mysqld(pfs_spawn_thread+0x140)[0x948880]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8182)[0x7f85d4797182]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f85d3eb9fbd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f8578005170): is an invalid pointer
Connection ID (thread ID): 2
Status: NOT_KILLED

[Valerii Kravchuk (valerii-kravchuk)]

Same with 5.6.39:

openxs@ao756:~/dbs/p5.5$ bash ~/ps_crash.sh
ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query
openxs@ao756:~/dbs/p5.5$ 140905 18:52:15 mysqld_safe Number of processes running now: 0
140905 18:52:15 mysqld_safe mysqld restarted

openxs@ao756:~/dbs/p5.5$ tail -100 data/ao756.err
140905 18:50:15 [ERROR] Aborting

140905 18:50:15 InnoDB: Starting shutdown...
140905 18:50:19 InnoDB: Shutdown completed; log sequence number 12744989
140905 18:50:19 [Note] /home/openxs/dbs/p5.5/bin/mysqld: Shutdown complete

140905 18:50:19 mysqld_safe mysqld from pid file /home/openxs/dbs/p5.5/data/ao756.pid ended
140905 18:50:45 mysqld_safe Starting mysqld daemon with databases from /home/openxs/dbs/p5.5/data
140905 18:50:45 [Note] Plugin 'FEDERATED' is disabled.
140905 18:50:45 InnoDB: The InnoDB memory heap is disabled
140905 18:50:45 InnoDB: Mutexes and rw_locks use GCC atomic builtins
140905 18:50:45 InnoDB: Compressed tables use zlib 1.2.3
140905 18:50:45 InnoDB: Using Linux native AIO
140905 18:50:45 InnoDB: Initializing buffer pool, size = 128.0M
140905 18:50:45 InnoDB: Completed initialization of buffer pool
140905 18:50:45 InnoDB: highest supported file format is Barracuda.
140905 18:50:45 InnoDB: Waiting for the background threads to start
140905 18:50:46 Percona XtraDB (http://www.percona.com) 5.5.39-36.0 started; log sequence number 12744989
140905 18:50:46 [Note] Event Scheduler: Loaded 0 events
140905 18:50:46 [Note] /home/openxs/dbs/p5.5/bin/mysqld: ready for connections.
Version: '5.5.39-36.0' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
15:52:15 UTC - mysqld got signal 11 ;
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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=1
max_threads=153
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 343008 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2585440
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 = 7f63b0256e70 thread_stack 0x40000
/home/openxs/dbs/p5.5/bin/mysqld(my_print_stacktrace+0x2c)[0x7c938c]
/home/openxs/dbs/p5.5/bin/mysqld(handle_fatal_signal+0x4a1)[0x6968c1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f63b41b3340]
/lib/x86_64-linux-gnu/libc.so.6(+0x140d5a)[0x7f63b3913d5a]
/home/openxs/dbs/p5.5/bin/mysqld[0x96bc6d]
/home/openxs/dbs/p5.5/bin/mysqld[0x8d2c41]
/home/openxs/dbs/p5.5/bin/mysqld[0x8d7ac5]
/home/openxs/dbs/p5.5/bin/mysqld[0x84cdb2]
/home/openxs/dbs/p5.5/bin/mysqld[0x825c91]
/ho...

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Valerii Kravchuk (valerii-kravchuk)]

Upstream MySQL 5.6.20 is also affected:

openxs@ao756:~/dbs/5.6$ bash ~/ps_crash.sh
ERROR 2013 (HY000) at line 1: Lost connection to MySQL server during query
openxs@ao756:~/dbs/5.6$ 140906 15:49:16 mysqld_safe Number of processes running now: 0
140906 15:49:16 mysqld_safe mysqld restarted

openxs@ao756:~/dbs/5.6$ tail -100 data/ao756.err
2014-09-06 15:47:28 8383 [Note] InnoDB: Highest supported file format is Barracuda.
2014-09-06 15:47:28 8383 [Note] InnoDB: 128 rollback segment(s) are active.
2014-09-06 15:47:28 8383 [Note] InnoDB: Waiting for purge to start
2014-09-06 15:47:28 8383 [Note] InnoDB: 5.6.20 started; log sequence number 265035407
2014-09-06 15:47:28 8383 [Warning] Plugin validate_password reported: 'Dictionary file not specified'
2014-09-06 15:47:28 8383 [Note] Server hostname (bind-address): '*'; port: 3306
2014-09-06 15:47:28 8383 [Note] IPv6 is available.
2014-09-06 15:47:28 8383 [Note] - '::' resolves to '::';
2014-09-06 15:47:28 8383 [Note] Server socket created on IP: '::'.
2014-09-06 15:47:29 8383 [Note] Event Scheduler: Loaded 0 events
2014-09-06 15:47:29 8383 [Note] /home/openxs/dbs/5.6/bin/mysqld: ready for connections.
Version: '5.6.20' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
12:49:16 UTC - mysqld got signal 11 ;
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=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 68245 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2755730
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 = 7f07c0281e50 thread_stack 0x40000
/home/openxs/dbs/5.6/bin/mysqld(my_print_stacktrace+0x2c)[0x8cf1cc]
/home/openxs/dbs/5.6/bin/mysqld(handle_fatal_signal+0x481)[0x66cda1]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x10340)[0x7f07d406a340]
/lib/x86_64-linux-gnu/libc.so.6(+0x1419b4)[0x7f07d35b59b4]
/home/openxs/dbs/5.6/bin/mysqld(_ZNSt8_Rb_treeIP14dict_foreign_tS1_St9_IdentityIS1_E20dict_foreign_compareSaIS1_EE11equal_rangeERKS1_+0x9d)[0xa777ed]
/home/openxs/dbs/5.6/bin/mysqld[0xa7721a]
/home/openxs/dbs/5.6/bin/mysqld[0x946851]
/home/openxs/dbs/5.6/bin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderb+0x2a89)[0x737509]
/home/openxs/dbs/5.6/bin/mysqld(_ZN19Sql_cmd_alter_table7executeEP3THD+0x49d)[0x81122d]
/home/openxs/dbs/5.6/bin/mysqld(_Z21mysql_execute_commandP3THD+0x33de)[0x6e88ce]
/home/openxs/dbs/5.6/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x378)[0x6ebb58]
/home/openxs/dbs/5.6/bin/mysqld(_Z16dispatch_comma...

[Richard Heelin (richardh)]

Valerii,

Feel free to use my script to report it upstream.

Richard

[Valerii Kravchuk (valerii-kravchuk)]

Please, check my upstream bug report: http://bugs.mysql.com/bug.php?id=73834

Note that it may be considered a "security" bug and disappear from public view soon.

[Robie Basak (racb)]

Not much we can do in Ubuntu without access to the upstream bug, except to update to a newer release when available.

[Laurynas Biveinis (laurynas-biveinis)]

A reduced testcase that produces bug 1364457 assert failure:

CREATE TABLE test_table (id INT UNSIGNED PRIMARY KEY) ENGINE=INNODB;
CREATE TABLE test_table1 (related_id INT UNSIGNED, FOREIGN KEY (related_id) REFERENCES test_table (id)) ENGINE=INNODB;
CREATE TABLE test_table2 (related_id INT UNSIGNED, FOREIGN KEY (related_id) REFERENCES test_table (id)) ENGINE=INNODB;
CREATE TABLE test_table3 (related_id INT UNSIGNED, FOREIGN KEY (related_id) REFERENCES test_table (id)) ENGINE=INNODB;
RENAME TABLE test_table1 TO testTable1;
ALTER TABLE testTable1 CHANGE COLUMN related_id relatedId INT UNSIGNED;

[Arkadiusz Miśkiewicz (arekm)]

https://code.launchpad.net/~laurynas-biveinis/percona-server/bug1366073-5.5

could be helpful

[Laurynas Biveinis (laurynas-biveinis)]

The fix in the branch in #12 as currently pushed is incomplete, please do not use it yet.

[Arkadiusz Miśkiewicz (arekm)]

FYI oracle mysql 5.5.40 got released with fix for this.

[Laurynas Biveinis (laurynas-biveinis)]

Indeed. We had reasons to think it is fixed only in 5.5.41, glad to see it in an earlier release.

[Arkadiusz Miśkiewicz (arekm)]

@Laurynas Biveinis: What does "fix released" mean in this case? Can't find anything never than percona-server-5.5.39-36.0.tar.gz

[Laurynas Biveinis (laurynas-biveinis)]

Arkadiusz, it means that the fix has been merged to the trunk and will be a part of the next release with a tentative version number 5.5.40-36.1. I don't have an ETA for it, but it should happen sooner than later.

[Arkadiusz Miśkiewicz (arekm)]

Ok, thanks (though usually "Fix Committed" is for that purpose).

[Arkadiusz Miśkiewicz (arekm)]

Here is fix for this issue only - https://github.com/mysql/mysql-server/commit/feac5e02ab298a5c3329ab63ee6db7d9f52bf28d.patch

[Arkadiusz Miśkiewicz (arekm)]

Earlier was for 5.5 and here is for 5.6:

https://github.com/mysql/mysql-server/commit/da00483beb3fe1375fc1ebeaac7943f73b56637e.patch

(needs adjustment or preapplying
https://github.com/mysql/mysql-server/commit/b54c850236f23c2aeb087bde53a9d975d0355486.patch)

[paulvas (paulvas)]

We are running Percona Server (GPL), Release 36.1, Revision 707 and issue is still not fixed.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Laurynas Biveinis (laurynas-biveinis)]

Paulvas -

Can you please file a new bug report?

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-815