Description:
If an alter table fails on a large database, on a table with several foreign key constraints, the server is completely unrecoverable. All subsequent schema operations, alter table, create table, drop database etc. fail. The client fails with "ERROR 2013 (HY000): Lost connection to MySQL server during query
", the server fails, usually with "[ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.", though sometimes with other errors.
The only solution I've discovered so far is to completely purge the MySQL software and reinstall from scratch.
Any attempt to create a new table after this crash creates the .frm file but not the .ibd file before crashing. Creating a new database works, but any attempt to create a new table in the new database fails.
InnoDB: ###### Diagnostic info printed to the standard error stream
2018-02-02T22:46:21.862665Z 0 [ERROR] [FATAL] InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung.
2018-02-02 22:46:21 0x7f0522d5a700 InnoDB: Assertion failure in thread 139660035991296 in file ut0ut.cc line 942
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
22:46:21 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.
key_buffer_size=16777216
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 = 76385 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x0
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 = 0 thread_stack 0x30000
/usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xe8f29b]
/usr/sbin/mysqld(handle_fatal_signal+0x489)[0x787029]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x11390)[0x7f053cb84390]
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x38)[0x7f053bf3d428]
/lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7f053bf3f02a]
/usr/sbin/mysqld[0x75ca3e]
/usr/sbin/mysqld(_ZN2ib5fatalD1Ev+0x145)[0x10573e5]
/usr/sbin/mysqld(srv_error_monitor_thread+0xe2d)[0xff46fd]
/lib/x86_64-linux-gnu/libpthread.so.0(+0x76ba)[0x7f053cb7a6ba]
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f053c00f41d]
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.
2018-02-02T22:46:22.089310Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)
2018-02-02T22:46:22.089351Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)
2018-02-02T22:46:22.321706Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2018-02-02T22:46:22.323320Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.21-0ubuntu0.16.04.1) starting as process 7262 ...
2018-02-02T22:46:22.339289Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-02-02T22:46:22.339311Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-02-02T22:46:22.339315Z 0 [Note] InnoDB: Uses event mutexes
2018-02-02T22:46:22.339321Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-02-02T22:46:22.339325Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-02-02T22:46:22.339329Z 0 [Note] InnoDB: Using Linux native AIO
2018-02-02T22:46:22.339567Z 0 [Note] InnoDB: Number of pools: 1
2018-02-02T22:46:22.339675Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-02-02T22:46:22.341168Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2018-02-02T22:46:22.361145Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-02-02T22:46:22.362617Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-02-02T22:46:22.374319Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-02-02T22:46:22.375591Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 11754135738
2018-02-02T22:46:22.375604Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 11754138493
2018-02-02T22:46:22.376179Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-02-02T22:46:22.376190Z 0 [Note] InnoDB: Starting crash recovery.
2018-02-02T22:46:22.490391Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-02-02T22:46:22.490415Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-02-02T22:46:22.490459Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-02-02T22:46:22.547058Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2018-02-02T22:46:22.547717Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-02-02T22:46:22.547727Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-02-02T22:46:22.548320Z 0 [Note] InnoDB: Waiting for purge to start
2018-02-02T22:46:22.598488Z 0 [Note] InnoDB: 5.7.21 started; log sequence number 11754138493
2018-02-02T22:46:22.598511Z 0 [Note] InnoDB: !!! innodb_force_recovery is set to 1 !!!
2018-02-02T22:46:22.598948Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-02-02T22:46:22.603740Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
2018-02-02T22:46:22.604855Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
2018-02-02T22:46:22.604868Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2018-02-02T22:46:22.604877Z 0 [Note] - '127.0.0.1' resolves to '127.0.0.1';
2018-02-02T22:46:22.604903Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2018-02-02T22:46:22.644175Z 0 [Note] Event Scheduler: Loaded 0 events
2018-02-02T22:46:22.644396Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.21-0ubuntu0.16.04.1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
2018-02-02T22:46:23.110615Z 2 [Note] Access denied for user 'root'@'localhost' (using password: NO)
2018-02-02T22:46:23.605120Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180202 22:46:23
How to repeat:
1. Create an Amazon EC2 / Ubuntu t2.medium in Sydney.
2. Install apache2, php, perl, mysql-server
3. Create a database which contains large tables, with foreign key constraints between the tables.
Database size 4981012Kb, vanilla mysql.cnf file created by a fresh install using sudo apt install mysql-server.
4. Attempt an alter one of the tables to add new columns (no keys).
5. If the alter table fails, the database is now in an unrecoverable state.
Suggested fix:
Code fix - the database engine should be recoverable, even if the database has to be dropped and re-created.