mysql启动失败分析_MySQL启动失败分析与解决

1, 背景

早上过来发现电脑非正常关机了，进mysql发现报错:

mysql -uroot -p

Enter password:

ERROR 2002 (HY000): Can"t connect to local MySQL server through socket "/var/run/mysqld/mysqld.sock" (2)

尝试启动mysql

sudo service mysql restart

报错

Job for mysql.service failed because the control process exited with error code. See "systemctl status mysql.service" and "journalctl -xe" for details.

查看错误信息

systemctl status mysql.service

● mysql.service - MySQL Community Server

Loaded: loaded (/lib/systemd/system/mysql.service; enabled; vendor preset: enabled)

Active: activating (start-post) (Result: exit-code) since 四 2019-11-28 14:57:56 CST; 12s ago

Process: 72098 ExecStart=/usr/sbin/mysqld (code=exited, status=1/FAILURE)

Process: 72091 ExecStartPre=/usr/share/mysql/mysql-systemd-start pre (code=exited, status=0/SUCCESS)

Main PID: 72098 (code=exited, status=1/FAILURE); : 72099 (mysql-systemd-s)

CGroup: /system.slice/mysql.service

└─control

├─72099 /bin/bash /usr/share/mysql/mysql-systemd-start post

└─72140 sleep 1

发现 /usr/sbin/mysqld 有报 FAILURE.

再看error.log文件，发现

2019-11-28T07:36:10.668476Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)

2019-11-28T07:36:10.668516Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)

2019-11-28T07:36:10.818941Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).

2019-11-28T07:36:10.818955Z 0 [Warning] "NO_ZERO_DATE", "NO_ZERO_IN_DATE" and "ERROR_FOR_DIVISION_BY_ZERO" sql modes should be used with strict mode. They will be merged with strict mode in a future release.

2019-11-28T07:36:10.818957Z 0 [Warning] "NO_AUTO_CREATE_USER" sql mode was not set.

2019-11-28T07:36:10.820037Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.28-0ubuntu0.16.04.2) starting as process 79313 ...

2019-11-28T07:36:10.823007Z 0 [Note] InnoDB: PUNCH HOLE support available

2019-11-28T07:36:10.823049Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2019-11-28T07:36:10.823073Z 0 [Note] InnoDB: Uses event mutexes

2019-11-28T07:36:10.823319Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

2019-11-28T07:36:10.823360Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8

2019-11-28T07:36:10.823375Z 0 [Note] InnoDB: Using Linux native AIO

2019-11-28T07:36:10.823554Z 0 [Note] InnoDB: Number of pools: 1

2019-11-28T07:36:10.823665Z 0 [Note] InnoDB: Using CPU crc32 instructions

2019-11-28T07:36:10.825004Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M

2019-11-28T07:36:10.830414Z 0 [Note] InnoDB: Completed initialization of buffer pool

2019-11-28T07:36:10.832436Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2019-11-28T07:36:10.844431Z 0 [Note] InnoDB: Highest supported file format is Barracuda.

2019-11-28T07:36:10.845399Z 0 [ERROR] InnoDB: Ignoring the redo log due to missing MLOG_CHECKPOINT between the checkpoint 6977823295 and the end 6977823254.

2019-11-28T07:36:10.845441Z 0 [ERROR] InnoDB: Plugin initialization aborted with error Generic error

2019-11-28T07:36:11.448706Z 0 [ERROR] Plugin "InnoDB" init function returned error.

2019-11-28T07:36:11.448738Z 0 [ERROR] Plugin "InnoDB" registration as a STORAGE ENGINE failed.

2019-11-28T07:36:11.448743Z 0 [ERROR] Failed to initialize builtin plugins.

2019-11-28T07:36:11.448746Z 0 [ERROR] Aborting

2019-11-28T07:36:11.448758Z 0 [Note] Binlog end

2019-11-28T07:36:11.448787Z 0 [Note] Shutting down plugin "MyISAM"

2019-11-28T07:36:11.448989Z 0 [Note] /usr/sbin/mysqld: Shutdown complete

其中几个 ERROR 级别的报错，redo log 由于 MLOG_CHECKPOINT有丢失而被忽略。InnoDB启动返回错误，注册成存储引擎失败。

2，分析

由于是非正常关机，MySQL重启要做事务重做，尝试着去回放redo log，而redo log就存放在datadir中，看my.cnf或者mysqld.cnf文件，可以看到

[mysqld]

#

# * Basic Settings

#

user = mysql

pid-file = /var/run/mysqld/mysqld.pid

socket = /var/run/mysqld/mysqld.sock

port = 3306

basedir = /usr

datadir = /var/lib/mysql

tmpdir = /tmp

lc-messages-dir = /usr/share/mysql

skip-external-locking

进/var/lib/mysql，可以看到两个文件，就是redo log:

-rw-r----- 1 mysql mysql 50331648 11月 28 00:04 ib_logfile0

-rw-r----- 1 mysql mysql 50331648 11月 26 22:26 ib_logfile1

根据error.log的日志，是因为redo log在两个checkpoint之间出现了缺失，导致重放失败，进而导致innoDB引擎注册失败。

这里的解决方法比较粗暴，直接把这两个文件删除，再重启mysql即可。

发现重启之后出现以下报错信息:

2019-11-28T07:38:43.167254Z 0 [Warning] Changed limits: max_open_files: 1024 (requested 5000)

2019-11-28T07:38:43.167291Z 0 [Warning] Changed limits: table_open_cache: 431 (requested 2000)

2019-11-28T07:38:43.318624Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).

2019-11-28T07:38:43.318639Z 0 [Warning] "NO_ZERO_DATE", "NO_ZERO_IN_DATE" and "ERROR_FOR_DIVISION_BY_ZERO" sql modes should be used with strict mode. They will be merged with strict mode in a future release.

2019-11-28T07:38:43.318640Z 0 [Warning] "NO_AUTO_CREATE_USER" sql mode was not set.

2019-11-28T07:38:43.319732Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.28-0ubuntu0.16.04.2) starting as process 79769 ...

2019-11-28T07:38:43.322788Z 0 [Note] InnoDB: PUNCH HOLE support available

2019-11-28T07:38:43.322816Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins

2019-11-28T07:38:43.322822Z 0 [Note] InnoDB: Uses event mutexes

2019-11-28T07:38:43.322825Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier

2019-11-28T07:38:43.322827Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.8

2019-11-28T07:38:43.322830Z 0 [Note] InnoDB: Using Linux native AIO

2019-11-28T07:38:43.323049Z 0 [Note] InnoDB: Number of pools: 1

2019-11-28T07:38:43.323195Z 0 [Note] InnoDB: Using CPU crc32 instructions

2019-11-28T07:38:43.324354Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M

2019-11-28T07:38:43.330117Z 0 [Note] InnoDB: Completed initialization of buffer pool

2019-11-28T07:38:43.331783Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().

2019-11-28T07:38:43.343837Z 0 [Note] InnoDB: Setting log file ./ib_logfile101 size to 48 MB

2019-11-28T07:38:43.906780Z 0 [Note] InnoDB: Setting log file ./ib_logfile1 size to 48 MB

2019-11-28T07:38:44.840035Z 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0

2019-11-28T07:38:44.840229Z 0 [Warning] InnoDB: New log files created, LSN=6838825544

2019-11-28T07:38:44.841027Z 0 [Note] InnoDB: Highest supported file format is Barracuda.

2019-11-28T07:38:44.843410Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 6838825996

2019-11-28T07:38:44.843500Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 6838826005

2019-11-28T07:38:44.843521Z 0 [Note] InnoDB: Database was not shutdown normally!

2019-11-28T07:38:44.843530Z 0 [Note] InnoDB: Starting crash recovery.

2019-11-28T07:38:44.872519Z 0 [ERROR] InnoDB: Page [page id: space=0, page number=7] log sequence number 6977817237 is in the future! Current system log sequence number 6838826014.

2019-11-28T07:38:44.872555Z 0 [ERROR] InnoDB: Your database may be corrupt or you may have copied the InnoDB tablespace but not the InnoDB log files. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.

这里看到InnoDB对log file进行了rename, 重新创建了日志文件

2019-11-28T07:38:44.840035Z 0 [Note] InnoDB: Renaming log file ./ib_logfile101 to ./ib_logfile0

2019-11-28T07:38:44.840229Z 0 [Warning] InnoDB: New log files created, LSN=6838825544

知道数据库之前没有正常关闭，开始crash恢复。

2019-11-28T07:38:44.843521Z 0 [Note] InnoDB: Database was not shutdown normally!

2019-11-28T07:38:44.843530Z 0 [Note] InnoDB: Starting crash recovery.

有一些因为crash，加上删除文件而导致的数据丢失。整体还是正常。