导读

有同事反应测试环境mysql突然挂了,而且起不来. 这种情况通常是磁盘满了导致的, 但这次不是.

数据库跑的好好的, 突然就挂了, 磁盘也很闲, 也没啥变更之类的. 就挺突然的.

简单看了下mysql的error日志, 发现数据库有大量的重启记录(Abort Server <–> ready for connections), 差不多每5-20秒就重启一次. 猜测是中了无限月读

不方便截图, 也不好复现. 就简单使用文字描述吧, 相关报错也手敲一下

分析过程

虽然在无限重启, 但是报错内容基本上是一样的, 如下:

starting as process xxxx....
....
[ERROR] Error in Log_event::read_log_event(): 'Event crc check faild! Most likely there is event corruption.' data_len:xxxx, event_type:29
[Note] Starting crash recovery.....
.....
[Note] mysqld: ready for connections.
...
[ERROR] mysqld: Binary logging not possible. Message: an error occurred during sync stage of the commit. 'binlog_error_action' is set to 'ABORT_SERVER'. Server is beging stopped.
.... 堆栈信息

然后是下一轮重启.

也就是mysql挂了, 然后mysqld_safe又把它拉起来了, 没多久又挂了, 然后mysqld_safe又把它拉起来了, 然后又挂了,又拉起来了, 又挂又拉…

初窥binlog

最先看到的是Event crc check faild, 我们前段时间不是写过binlog校验原理的么, 这用途不就来了么. 但我们还是使用mysqlbinlog来检查, 毕竟官方也支持, 我的脚本无法上传,手敲也要花不少时间的.

mysqlbinlog --verify-binlog-checksum mysql-bin.0* >/dev/null

检查了下, 居然没得坏块, 欸, 这就离谱了, 毕竟日志里面都报错event校验失败了啊.

还有种可能: mysqlbinlog有问题! 本来准备上传我们的Binlog脚本来验证的, 但终究流程太复杂了, 而且这一步并没有导致数据库宕掉, 反而还是正常启动了. 再说了, 后面不是还有一条报错么.

再探binlog

后面一条报错(Binary logging not possible. Message: an error occurred during sync stage of the commit. ‘binlog_error_action’ is set to ‘ABORT_SERVER’. Server is beging stopped)才是导致数据库宕机的真相.

从描述来看是binlog在sync阶段的时候出问题了.

关于binlog的sync阶段干嘛的, 可以看下之前的两阶段提交. 我们这里是sync的时候有问题的, 有个类似的issue是flush的时候出问题的: https://bugs.mysql.com/bug.php?id=95547

这不还是binlog的锅么, 通常这种是文件系统full了, 但这次未看到相关报错, 手动df看了文件系统也非常的充足. 那我们就来看下源码, 哪些情况会导致这个报错. 我们查询了下源码(可以使用万能的grep -r,也可以直接看堆栈信息):

/*sql/binlog.cc*/
int MYSQL_BIN_LOG::ordered_commit(THD *thd, bool all, bool skip_commit){
...
sync_error= call_after_sync_hook(commit_queue);
....
  /*
    Handle sync error after we release all locks in order to avoid deadlocks
  */
  if (sync_error)
    handle_binlog_flush_or_sync_error(thd, true /* need_lock_log */, NULL);

  /* Commit done so signal all waiting threads */
  stage_manager.signal_done(final_queue);
...
}


void MYSQL_BIN_LOG::handle_binlog_flush_or_sync_error(THD *thd,
                                                      bool need_lock_log,
                                                      const char* message)
{
  char errmsg[MYSQL_ERRMSG_SIZE]= {0};
  if (!message)
    sprintf(errmsg, "An error occurred during %s stage of the commit. "
            "'binlog_error_action' is set to '%s'.",
            thd->commit_error== THD::CE_FLUSH_ERROR ? "flush" : "sync",
            binlog_error_action == ABORT_SERVER ? "ABORT_SERVER" : "IGNORE_ERROR");
  else
    strncpy(errmsg, message, MYSQL_ERRMSG_SIZE-1);
  if (binlog_error_action == ABORT_SERVER)
  {
    char err_buff[MYSQL_ERRMSG_SIZE + 25];
    sprintf(err_buff, "%s Server is being stopped.", errmsg);
    exec_binlog_error_action_abort(err_buff);
  }
  else
.....
}

简单的描述下就是: ordered_commit做sync的时候返回了ERROR,然后打印了相关报错信息,并abort. 也就是说可能是磁盘/文件系统的问题.

转锅给文件系统

那我们就验证下文件系统是否有问题吧. 首先我们随便拷贝了一个其它文件系统的文件过来

cp -ra @@datadir/ibdata1 binlogdir/

居然没报错! 当然也可能是缓存之类的, 所以我们再把它mv走实现.

mv binlogdir/ibdata1 /tmp

这一步居然卡住了(ibdata1才几十MB), 诶, 这不就是文件系统的锅了么.

实际上每次重启都还rotate一个新的binlog, 所以文件系统写应该没啥问题. 读就不好说了. 毕竟日志里面都报错binlog crc校验失败了.

也就是说: 这个Binlog所在的文件系统可以写(实际上也有问题), 但不能读.(挂载权限之类的是没有动过的).

这种系统级别的报错, 一般都有相关报错的. 我们使用dmesg -T查看下系统日志, 发现如下信息

XFS (dm-10): metadata I/O error in "xfs_trans_read_buf_map" at daddr 0xf00003 len 1 error 74
XFS (dm-10): page discard on page 000XXXXXXXX, inode 0xXXXXX, offset xxxxx
MEtadata CRC error deleted at xfs_agfl_read_verify+0xa5/0xf0 [xfs], xfs_agfl block 0xf00003
XFS (dm-10): Unmount and run xfs_repair
XFS (dm-10): First 128 bytes of corrupted metadata buffer:
xxxx 具体的meta信息(全部被置为0x00了,被dd了?)

日志已经写得很明显了, xfs读的时候有error了. 具体的我们就不看了, 如果对xfs文件系统感兴趣, 可以看下之前的解析xfs文件系统的文章. 还能恢复drop/rm之类的文件哦.

处理方法

既然原因已经找到了, 那么解决办法就比较简单了(日志里面也有提示的): 卸载该文件系统并使用xfs_repair修复. 文件系统有问题的时候, 实际上可能umount不掉, 所以可以注释/etc/fstab和`相关的crontab然后重启OS. 重启之后再修复

xfs_repair /dev/mapper/binlogdir

修复之后再重新挂载, 然后启动mysqld. 发现启动成功了.

问题来了, 如果xfs_repaire修复失败该怎么办呢?(不要Binlog? 人工解析xfs?)

总结

本次的"mysql无限重启"的真相就是文件系统坏了导致数据库挂了,mysqld_safe又把mysql拉起来, 拉起来之后又挂了,就循环上了.

虽然本次案例不常见(运行中的存储很少遇到有问题的, 多数都是搬迁/重启的时候有问题), 也不算难(耗时20分钟左右), 但方法和思路还是可以借鉴的.故分享出来.

开始我们以为是binlog有问题, 但是使用mysqlbinlog校验的时候未发现像问题, 数据也是能够解析出来的. 这说明那部分数据应该都写成功了的(也可能是在xfs日志位置), repair之后也能看到. 而我们手动拷贝过去的文件是空的(也可能跟后面执行mv有关系,不好验证了), 有兴趣的可以自己研究下.

mysql运维久了, 可能遇到的mysql问题就少了(多数都知道了,能避免的都避免了, 不能避免的心里也都有数了), 然后遇到一些非mysql本身导致的问题, 这时有一些非mysql的基础知识就比较重要了, 尤其是Linux. 如果还能会一丢丢编程就更好了