1. 背景
在做MySQL5.5 升级 MySQL 5.6, MySQL 5.5 版本为 5.5.18, MySQL 5.6 版本为 5.6.29,升级过程中,启动5.6 的MySQL Server时,MySQL Server 启动不了,查看错误日志,发现 mysqld got signal 11, 详细日志如下:
190314 09:01:11 mysqld_safe Starting mysqld daemon with databases from /mysql/data
2019-03-14 09:01:14 0 [Warning] 'THREAD_CONCURRENCY' is deprecated and will be removed in a future release.
2019-03-14 09:01:14 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2019-03-14 09:01:14 0 [Note] /usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld (mysqld 5.6.29-76.2-log) starting as process 26927 ...
2019-03-14 09:01:14 26927 [Warning] Using unique option prefix myisam_recover instead of myisam-recover-options is deprecated and will be removed in a future release. Please use the full name instead.
2019-03-14 09:01:14 26927 [Note] Plugin 'FEDERATED' is disabled.
2019-03-14 09:01:14 26927 [Warning] option 'innodb-purge-threads': unsigned value 0 adjusted to 1
2019-03-14 09:01:14 7fb3d0c09840 InnoDB: Warning: Using innodb_additional_mem_pool_size is DEPRECATED. This option may be removed in future releases, together with the option innodb_use_sys_malloc and with the InnoDB's internal memory allocator.
2019-03-14 09:01:14 26927 [Note] InnoDB: Using atomics to ref count buffer pool pages
2019-03-14 09:01:14 26927 [Note] InnoDB: The InnoDB memory heap is disabled
2019-03-14 09:01:14 26927 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2019-03-14 09:01:14 26927 [Note] InnoDB: Memory barrier is not used
2019-03-14 09:01:14 26927 [Note] InnoDB: Compressed tables use zlib 1.2.3
2019-03-14 09:01:14 26927 [Note] InnoDB: Using Linux native AIO
2019-03-14 09:01:14 26927 [Note] InnoDB: Using CPU crc32 instructions
2019-03-14 09:01:14 26927 [Note] InnoDB: Initializing buffer pool, size = 1.0G
2019-03-14 09:01:14 26927 [Note] InnoDB: Completed initialization of buffer pool
2019-03-14 09:01:14 26927 [Note] InnoDB: Highest supported file format is Barracuda.
2019-03-14 09:01:14 26927 [Note] InnoDB: Log scan progressed past the checkpoint lsn 13263385150
2019-03-14 09:01:14 26927 [Note] InnoDB: Database was not shutdown normally!
2019-03-14 09:01:14 26927 [Note] InnoDB: Starting crash recovery.
2019-03-14 09:01:14 26927 [Note] InnoDB: Reading tablespace information from the .ibd files...
2019-03-14 09:01:14 26927 [Note] InnoDB: Restoring possible half-written data pages
2019-03-14 09:01:14 26927 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 13268627968
InnoDB: Doing recovery: scanned up to log sequence number 13273870848
InnoDB: Doing recovery: scanned up to log sequence number 13279113728
InnoDB: Doing recovery: scanned up to log sequence number 13284356608
InnoDB: Doing recovery: scanned up to log sequence number 13289599488
InnoDB: Doing recovery: scanned up to log sequence number 13294842368
InnoDB: Doing recovery: scanned up to log sequence number 13300085248
InnoDB: Doing recovery: scanned up to log sequence number 13305328128
InnoDB: Doing recovery: scanned up to log sequence number 13310571008
InnoDB: Doing recovery: scanned up to log sequence number 13315813888
InnoDB: Doing recovery: scanned up to log sequence number 13320693045
InnoDB: 8 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 14 row operations to undo
InnoDB: Trx id counter is 32768
2019-03-14 09:01:18 26927 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 0 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
01:01:30 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=2097152
max_used_connections=0
max_threads=2402
thread_count=0
connection_count=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 9880041 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/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld(my_print_stacktrace+0x2c)[0x8f8bbc]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld(handle_fatal_signal+0x461)[0x67de61]
/lib64/libpthread.so.0(+0xf7e0)[0x7fb3d05b17e0]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0xac3918]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0xac4bac]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0xa2be7b]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0x96bbe1]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x48)[0x5bf8f8]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0x70b921]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld(_Z11plugin_initPiPPci+0x941)[0x711d51]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0x5b825d]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld(_Z11mysqld_mainiPPc+0x3fd)[0x5b92bd]
/lib64/libc.so.6(__libc_start_main+0xfd)[0x7fb3cf10cd5d]
/usr/local/Percona-Server-5.6.29-rel76.2-Linux.x86_64.ssl101/bin/mysqld[0x5ab49d]
You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
190314 09:01:31 mysqld_safe mysqld from pid file /mysql/data/sndsdevapp17.pid ended
2. 排查分析
通过分析错误日志,发现有MySQL redo log 故障恢复重做的信息,也就是MySQL5.5非正常关闭。升级脚本里,在关闭MySQL5.5时,设置了10秒的超时时间,如果10秒内,MySQL5.5没有关闭,就会kill -9 强杀。
问题就在这里了, 如果kill -9 强杀了MySQL5.5, 后面再用MySQL5.6启动数据库,也就会使用5.6的redo log 重做事务的逻辑,由于5.5与5.6在某些数据格式上的差别,最终导致了5.6启动失败,报了mysqld got signal 11的错误信息。
基于以上分析,在测试环境,复现了该问题。
3. 解决方案
-
关闭MySQL5.5时,设置:SET GLOBAL innodb_fast_shutdown=0, 这也是官方升级流程里提到的。
关闭MySQL5.5时,超时时间设置长一点,决不能kill -9强杀MySQL Server后,再用5.6 来启动数据库。