溫馨提示×

您好，登錄后才能下訂單哦！

密碼登錄×
登錄注冊(cè)×
其他方式登錄
點(diǎn)擊 登錄注冊(cè) 即表示同意《億速云用戶服務(wù)條款》

MySQL案例-初步恢復(fù): alter引起的從庫無限Crash

發(fā)布時(shí)間：2020-08-15 20:13:13 來源：ITPUB博客 閱讀：500 作者：wangwenan6 欄目：MySQL數(shù)據(jù)庫
-------------------------------------------------------------------------------------------------正文---------------------------------------------------------------------------------------------------------------

場(chǎng)景 : 
Crash發(fā)生時(shí)的數(shù)據(jù)庫版本: MySQL-5.7.17, 從庫在同步到某一個(gè)alter語句的時(shí)候發(fā)生了Crash, 并且在重啟進(jìn)行Crash Recovery的時(shí)候不斷觸發(fā)同一個(gè)錯(cuò)誤導(dǎo)致Crash;

結(jié)論 :
只讀業(yè)務(wù)臨時(shí)切換到另外一個(gè)只讀實(shí)例, 且重新做一個(gè)從庫給業(yè)務(wù)用;

重點(diǎn)! : 
解決問題的辦法肯定不是把庫恢復(fù)起來, 而是重新做一個(gè), 所以本文記錄的操作主要目的是做實(shí)踐和嘗試, 生產(chǎn)環(huán)境上請(qǐng)謹(jǐn)慎操作;


場(chǎng)景:
生產(chǎn)環(huán)境的場(chǎng)景, 屏蔽一些敏感信息;

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

點(diǎn)擊(此處)折疊或打開

  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重啟進(jìn)行Crash Recovery的日志;

可以從紅色標(biāo)記的地方看到, 其實(shí)第一次重啟的時(shí)候, crash recovery就已經(jīng)完成了, 而且mysqld進(jìn)程也已經(jīng)ready for connections,
但是馬上就觸發(fā)了同樣的問題, 導(dǎo)致mysql又發(fā)生了Crash, 而且mysqld_safe也跟著"消失"了;

在之后的重啟嘗試中, 每次在Crash之前, 都有這么一行信息:

點(diǎn)擊(此處)折疊或打開

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

結(jié)合堆棧信息中顯示出來的fsp0fsp.cc line 2108, 在源代碼中找到這一行(紅色標(biāo)注),


點(diǎn)擊(此處)折疊或打開

  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.         }

結(jié)合日志中的cleanup階段的log和阿里的mysql內(nèi)核月報(bào)中對(duì)innodb的分析可以知道, alter語句在drop 索引的時(shí)候會(huì)調(diào)用到這個(gè)方法的, 用來回收數(shù)據(jù)頁/返還表空間;

所以問題基本確定就是alter語句引起了這次mysql的Crash, 且每次重啟的時(shí)候都在同樣一個(gè)位置報(bào)錯(cuò)說明這個(gè)alter ... drop index的數(shù)據(jù)頁并沒有完成cleanup, 每次重啟的時(shí)候都在嘗試, 然后觸發(fā)Crash;

由于觸發(fā)Crash的階段始終都處于Crash Recovery之后,  所以推斷mysql可能是在處于rollback階段, 所以設(shè)置了innodb_force_recovery = 3,
發(fā)現(xiàn)跳過rollback以后數(shù)據(jù)庫正常的起來了~\(≧▽≦)/~

那么事情就好辦了, innodb_force_recovery = 3的時(shí)候是可以對(duì)表進(jìn)行操作的, 比如說.....drop.....

在第一次Crash的日志里面, 可以看到tb0和tb1的alter可能都有問題, 因?yàn)閍lter產(chǎn)生的中間結(jié)果表還在data目錄下;
所以為了不再讓rollback觸發(fā)alter語句cleanup的問題, 最簡(jiǎn)單的辦法就是......drop掉這兩個(gè)表~\(≧▽≦)/~

_(:з」∠)_ 當(dāng)然不能直接drop...先dump出來.....
不過實(shí)際操作之前, 先確認(rèn)一下當(dāng)前數(shù)據(jù)庫的狀態(tài):

從庫復(fù)現(xiàn)主庫的事務(wù), 停留在這個(gè)階段: 8fc6463a-f9b1-11e6-b218-ce0e1b052154:1-2241902370:2241902372-2241902383;
通過查看relaylog, 找到遺漏的2241902371事務(wù), 正好是alter語句
MySQL案例-初步恢復(fù): alter引起的從庫無限Crash
MySQL案例-初步恢復(fù): alter引起的從庫無限Crash

這里面有幾個(gè)比較重要的信息, 除了GTID和SQL以外, 還有一個(gè): last_committed=91691

再看看2241902383之后的事務(wù)是什么
MySQL案例-初步恢復(fù): alter引起的從庫無限Crash

那么就基本確認(rèn)了, 當(dāng)前的狀態(tài)是91692的事務(wù)組中, 除了2241902371以外全部提交成功, 而下一個(gè)事務(wù)組91693還沒有開始;

再查一下有問題的tb0和tb1, 確認(rèn)2241902371事務(wù)對(duì)應(yīng)的表結(jié)構(gòu)確實(shí)是沒有主鍵, 那么說明這個(gè)語句確實(shí)沒有執(zhí)行, 所以目前的庫應(yīng)該是處于一致的狀態(tài)的(Crash Recovery成功了是大前提)
我們開始著手讓mysql啟動(dòng)起來~

_(:з」∠)_ 先把tb0和tb1都dump出來.....
~\(≧▽≦)/~ 然后drop掉~(如果之后需要重建同步的話, 記得關(guān)掉sql_log_bin, 不要把drop語句寫到binlog)
(⊙﹏⊙)再去掉配置文件的innodb_force_recovery, 重啟mysql.....

done, 數(shù)據(jù)庫正常起來了~

之后就簡(jiǎn)單了, 重新把這兩張表導(dǎo)入到數(shù)據(jù)庫, 再開啟同步, 看看同步的狀態(tài):
MySQL案例-初步恢復(fù): alter引起的從庫無限Crash

可以看到缺少的2241902371事務(wù)已經(jīng)重新拉取下來了, 而且2241902384和之后的事務(wù)也正常的拉取和執(zhí)行了~

等到同步同步跟上的時(shí)候, 就可以驗(yàn)證一下數(shù)據(jù)是不是真的一致了~

PS: 由于在重啟的過程中, MTR和Crash Recovery都成功了, 而且同步狀態(tài)正常, GTID的事務(wù)號(hào)也保持了連續(xù), 從個(gè)人角度來看, 更加傾向于數(shù)據(jù)是一致的~
PPS: 這個(gè)庫能交付給用戶繼續(xù)使用么? 雖然不推薦就這么交付回去, 不過用戶說能用, 那就能用~
向AI問一下細(xì)節(jié)

免責(zé)聲明：本站發(fā)布的內(nèi)容（圖片、視頻和文字）以原創(chuàng)、轉(zhuǎn)載和分享為主，文章觀點(diǎn)不代表本網(wǎng)站立場(chǎng)，如果涉及侵權(quán)請(qǐng)聯(lián)系站長(zhǎng)郵箱：is@yisu.com進(jìn)行舉報(bào)，并提供相關(guān)證據(jù)，一經(jīng)查實(shí)，將立刻刪除涉嫌侵權(quán)內(nèi)容。

AI
助
手