MySQL案例-初步恢复: alter引起的从库无限Crash

————————————————————————————————-正文—————————————————————————————————————

场景 : 
Crash发生时的数据库版本: MySQL-5.7.17, 从库在同步到某一个alter语句的时候发生了Crash, 并且在重启进行Crash Recovery的时候不断触发同一个错误导致Crash;

结论 :
只读业务临时切换到另外一个只读实例, 且重新做一个从库给业务用;

重点! : 
解决问题的办法肯定不是把库恢复起来, 而是重新做一个, 所以本文记录的操作主要目的做实践和尝试, 生产环境上请谨慎操作;

场景:
生产环境的场景, 屏蔽一些敏感信息;

首先截取Error log中比较的重要信息:

点击(此处)折叠或打开

  1. 2017-05-25 14:10:23 0x7f9b5b927700 InnoDB: Assertion failure in thread 140305232983808 in file fsp0fsp.cc line 2108
  2. InnoDB: Failing assertion: frag_n_used > 0
  3. ……
  4. /usr/sbin/mysqld(_Z14fseg_free_stepPhbP5mtr_t+0x36e)[0x11d073e]
  5. ……
  6. /usr/sbin/mysqld(_Z23trx_undo_insert_cleanupP14trx_undo_ptr_tb+0x16c)[0x1100b9c]
  7. ……
  8. /usr/sbin/mysqld(_Z19innobase_commit_lowP5trx_t+0x17)[0xf6a0e7]
  9. /usr/sbin/mysqld(_ZN15Query_log_event14do_apply_eventEPK14Relay_log_infoPKcm+0x68d)[0xdf4c1d]
  10. /usr/sbin/mysqld(_Z27slave_worker_exec_job_groupP12Slave_workerP14Relay_log_info+0x293)[0xe52353]
  11. ……
  12. /usr/sbin/mysqld(handle_slave_worker+0x363)[0xe34f73]
  13. ……
  14. Trying to get some variables.
  15. Some pointers may be invalid and cause the dump to abort.
  16. Query (xxxxxxxxx): alter table tb1 add primary key(`col1`,`col2`,`col3`)
  17. Connection ID (thread ID): 129443
  18. Status: NOT_KILLED
  19. ……
  20. 2017-05-25T14:10:24.858719+08:00 0 [Note] InnoDB: Ignoring data file ‘./dbname/tb0.ibd‘ with space ID 375, since the redo log references ./dbname/tb0.ibd with space ID 280.
  21. 2017-05-25T14:10:24.860628+08:00 0 [Note] InnoDB: Ignoring data file ‘./dbname/tb1.ibd‘ with space ID 374, since the redo log references ./dbname/tb1.ibd with space ID 279.
  22. ……
  23. 2017-05-25T14:10:44.635655+08:00 0 [Note] InnoDB: Ignoring data file ‘./dbname/#sql-7b4e1_9f3a1.ibd’ with space ID 375. Another data file called ./dbname/tb0.ibd exists with the same space ID.
  24. ……
  25. 2017-05-25T14:10:39.845947+08:00 0 [Note] InnoDB: Ignoring data file ‘./dbname/#sql-7b4e1_9f3a1.ibd’ with space ID 374. Another data file called ./report_gamein/t30741_hs_g47_day.ibd exists with the same space ID.
  26. ……
  27. 2017-05-25T14:11:02.972181+08:00 0 [Note] Starting crash recovery…
  28. 2017-05-25T14:11:02.972227+08:00 0 [Note] Crash recovery finished.
  29. 2017-05-25T14:11:40.547210+08:00 0 [Note] InnoDB: Rollback of trx with id 3377056858 completed
  30. 2017-05-25T14:11:40.554385+08:00 0 [Note] InnoDB: Rollback of non-prepared transactions completed
  31. ……
  32. 2017-05-25T14:11:03.752024+08:00 0 [Warning] Recovery from master pos 43851595 and file binlog.006933 for channel ‘amaster‘. Previous relay log pos and relay log file had been set to 43851818, /home/mysql/log/relaylog/relaylog-amaster_3537.020527 respectively.
  33. ……
  34. 2017-05-25T14:11:03.817050+08:00 0 [Warning] Recovery from master pos 789680988 and file binlog.027468 for channel ‘bmaster. Previous relay log pos and relay log file had been set to 789681243, /home/mysql/log/relaylog/relaylog-bmaster_3637.020768 respectively.
  35. ……
  36. 2017-05-25T14:11:04.353863+08:00 0 [Note] /usr/sbin/mysqld: ready for connections.
  37. Version: ‘5.7.17-log’  socket: ‘/home/mysql/data/mysqld.sock’  port: 3306  MySQL Community Server (GPL)
  38. 2017-05-25 14:11:04 0x7f10762de700  InnoDB: Assertion failure in thread 139708678924032 in file fsp0fsp.cc line 2108
    InnoDB: Failing assertion: frag_n_used > 0
  39. ……

截取出来的是第一次遇到问题, mysql重启进行Crash Recovery的日志;

可以从红色标记的地方看到, 其实第一次重启的时候, crash recovery就已经完成了, 而且mysqld进程也已经ready for connections,
但是马上就触发了同样的问题, 导致mysql又发生了Crash, 而且mysqld_safe也跟着”消失”了;

在之后的重启尝试中, 每次在Crash之前, 都有这么一行信息:

点击(此处)折叠或打开

  1. 2017-05-25T15:25:33.025244+08:00 0 [Note] InnoDB: Cleaning up trx with id 3377057419

结合堆栈信息中显示出来的fsp0fsp.cc line 2108, 在源代码中找到这一行(红色标注),

点击(此处)折叠或打开

  1. fsp_free_page(
            const page_id_t&        page_id,
            const page_size_t&      page_size,
            mtr_t*                  mtr)

  2. ……
  3. if (state == XDES_FULL_FRAG) {
  4.                 /* The fragment was full: move it to another list */
  5.                 flst_remove(header + FSP_FULL_FRAG, descr + XDES_FLST_NODE,
  6.                             mtr);
  7.                 xdes_set_state(descr, XDES_FREE_FRAG, mtr);
  8.                 flst_add_last(header + FSP_FREE_FRAG, descr + XDES_FLST_NODE,
  9.                               mtr);
  10.                 mlog_write_ulint(header + FSP_FRAG_N_USED,
  11.                                  frag_n_used + FSP_EXTENT_SIZE - 1,
  12.                                  MLOG_4BYTES, mtr);
  13.         } else {
  14.                 ut_a(frag_n_used > 0);
  15.                 mlog_write_ulint(header + FSP_FRAG_N_USED, frag_n_used - 1,
  16.                                  MLOG_4BYTES, mtr);
  17.         }

结合日志中的cleanup阶段的log和阿里的mysql内核月报中对innodb的分析可以知道, alter语句在drop 索引的时候会调用到这个方法的, 用来回收数据页/返还表空间;

所以问题基本确定就是alter语句引起了这次mysql的Crash, 且每次重启的时候都在同样一个位置报错说明这个alter … drop index的数据页并没有完成cleanup, 每次重启的时候都在尝试, 然后触发Crash;

由于触发Crash的阶段始终都处于Crash Recovery之后,  所以推断mysql可能是在处于rollback阶段, 所以设置了innodb_force_recovery = 3,
发现跳过rollback以后数据库正常的起来了~/(≧▽≦)/~

那么事情就好办了, innodb_force_recovery = 3的时候是可以对表进行操作的, 比如说…..drop…..

在第一次Crash的日志里面, 可以看到tb0和tb1的alter可能都有问题, 因为alter产生的中间结果表还在data目录下;
所以为了不再让rollback触发alter语句cleanup的问题, 最简单的办法就是……drop掉这两个表~/(≧▽≦)/~

_(:з」∠)_ 当然不能直接drop…先dump出来…..
不过实际操作之前, 先确认一下当前数据库的状态:

从库复现主库的事务, 停留在这个阶段: 8fc6463a-f9b1-11e6-b218-ce0e1b052154:1-2241902370:2241902372-2241902383;
通过查看relaylog, 找到遗漏的2241902371事务, 正好是alter语句
MySQL案例-初步恢复: alter引起的从库无限Crash
MySQL案例-初步恢复: alter引起的从库无限Crash

这里面有几个比较重要的信息, 除了GTID和SQL以外, 还有一个: last_committed=91691

再看看2241902383之后的事务是什么
MySQL案例-初步恢复: alter引起的从库无限Crash

那么就基本确认了, 当前的状态是91692的事务组中, 除了2241902371以外全部提交成功, 而下一个事务组91693还没有开始;

再查一下有问题的tb0和tb1, 确认2241902371事务对应的表结构确实是没有主键, 那么说明这个语句确实没有执行, 所以目前的库应该是处于一致的状态的(Crash Recovery成功了是大前提)
我们开始着手让mysql启动起来~

_(:з」∠)_ 先把tb0和tb1都dump出来…..
~/(≧▽≦)/~ 然后drop掉~(如果之后需要重建同步的话, 记得关掉sql_log_bin, 不要把drop语句写到binlog)
(⊙﹏⊙)再去掉配置文件的
innodb_force_recovery, 重启mysql…..

done, 数据库正常起来了~

之后就简单了, 重新把这两张表导入到数据库, 再开启同步, 看看同步的状态:
MySQL案例-初步恢复: alter引起的从库无限Crash

可以看到缺少的2241902371事务已经重新拉取下来了, 而且2241902384和之后的事务也正常的拉取和执行了~

等到同步同步跟上的时候, 就可以验证一下数据是不是真的一致了~

PS: 由于在重启的过程中, MTR和Crash Recovery都成功了, 而且同步状态正常, GTID的事务号也保持了连续, 从个人角度来看, 更加倾向于数据是一致的~
PPS: 这个库能交付给用户继续使用么? 虽然不推荐就这么交付回去, 不过用户说能用, 那就能用~

PS:如果您想和业内技术大牛交流的话,请加qq群(527933790)或者关注微信公众 号(AskHarries),谢谢!

转载请注明原文出处:Harries Blog™ » MySQL案例-初步恢复: alter引起的从库无限Crash

赞 (0)

分享到:更多 ()

评论 0

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址