梳理下MySQL崩潰恢復過程

基於MySQL5.7版本，5.7版本在恢復過程作了優化，本文描述不考慮以前版本。

1 初始化崩潰恢復

    數據庫關閉只有2種狀況，正常關閉，非正常關閉（包括數據庫實例crash及服務器crash）。

    正常關閉狀況，全部buffer pool裏邊的髒頁都會都會刷新一遍到磁盤，同時記錄最新LSN到ibdata文件的第一個page中。而非正常關閉來不及作這些操做，也就是沒及時把髒數據flush到磁盤，也沒有記錄最新LSN到ibdata file。

    當咱們重啓數據庫實例的時候，數據庫作2個階段性操做：redo log處理，undo log及binlog 處理。

1.1 redo log處理

• 打開系統表空間ibdata，讀取第一個page中的LSN，若第一個頁損壞，則依次日後面的page讀，知道有個完整的page可以提供LSN，這個LSN看成上次shutdown時的checkpoint點，後續恢復，從這個LSN點開始恢復

• 進入redo log文件，讀取第一個redo log文件頭的checkpoint LSN， 並根據該LSN定位到redo日誌文件中對應的位置，從該checkpoint點開始掃描，進行3次redo log文件掃描：

• • 第一次，找 MLOG_CHECKPOINT日誌

• • • 若是是正常關閉，這個日誌是不作記錄的，也就是掃描的過程當中不回找到對應的MLOG_CHECKPOINT日誌，不會進行接下來的兩次掃描，由於屬於正常關閉數據庫服務，不須要考慮奔潰恢復狀況；

• • • 若是是非正常關閉，則會查找到 MLOG_CHECKPOINT （若是是多個，則說明redo文件已損壞，恢復報錯），獲取MLOG_FILE_NAME中指定後續須要恢復的ibd文件；

• • 第二次，從redo log讀到的LSN，找到checkpoint點開始重複掃描存儲日誌對象

• • • 根據MLOG_CHECKPOINT日誌，讀取對應LSN以後的日誌解析到hash表中，若是剩下的日誌解析結束後尚未填滿hash表格，則不須要進行第三次掃描；

• • • 進行到這裏，則說明數據庫是非正常關閉，會在errorlog中提示：Database was not shutdown normally!詳見下圖。

• • 第三次，若第二次掃描hash表空間不足，則發起第三次掃描，清空hash表空間，從新重新的checkpoint點開始掃描

• • • 若是第二次掃掃描就把hash表填滿，那麼會先把hash表裏邊的記錄重作到buffer pool中的數據頁，而後再來加載redo log 記錄到被清空的hash表中，hash表滿後當即執行恢復操做，知道全部須要redo 的redo log 被應用結束。

    恢復的過程當中，注意兩個點：打開ibd文件形式，讀取數據庫到buffer pool的改進。

    根據hash表中的相應信息讀取數據頁， 讀數據頁的時候，5.7以前版本採用把全部表空間都打開，全部表格僅執行ReadOnly，5.7版本作了優化，新增了 MLOG_FILE_NAME 記錄在checkpoint以後，全部被修改過的信息，根據這些信息，在恢復過程當中，只須要打開相應的ibd文件便可，不涉及恢復的表格支持正常DML跟DDL操做，涉及恢復的表格則僅執行ReadOnly功能。

    當把數據頁讀取到buffer pool中，以往版本是隻讀取對應的 單個頁面，而如今的是直接讀取與該頁面相鄰的32個data page 也一塊兒加載的buffer pool，由於一個數據頁的修改，可能周圍的頁面也被修改，一次性讀取，能夠避免後面根據hash表中再從新讀取其相鄰的頁面。

1.2 undo log及binlog 處理

      上一階段中，把redo log中的操做都apply到數據頁中，可是對於prepare狀態的事務卻尚未進行回滾處理，這個階段則是針對prepare狀態的事務進行處理，須要使用到binlog和undo log。

• 根據最後一個binlog文件，爲啥不是全部binlog文件呢？由於每個binlog文件切換的時候，都會確保當前binlog文件的全部操做已落盤，因此只須要考慮最後一個binlog文件。跟進最後一個binlog文件，獲取全部可能沒有提交事務的xid列表；

• 根據undo log中的 insert_undo_list，upddate_undo_list事務鏈，構建undo_list，在根據undo_list構建未提交事務鏈表;

• 從未提交事務鏈表中，提取出xid，凡是存在於xid列表中的，則須要提交，不存在的，則回滾。

      整個恢復過程，能夠參考下來自 www.sysdb.cn 網站做者  boyce 畫的說明圖，圖片版權屬於該做者，本處僅爲引用分享給你們，做圖很詳細，一言不合開源碼分析！遺憾的是，做者只寫了2篇博文就中止更新了，心疼默哀十分鐘.....

2 innodb關閉恢復涉及參數

2.1 關閉參數：innodb_fast_shutdown

    數據庫關閉的時候，innodb須要完成全部full purge何insert buffer操做，這須要一些時間，甚至幾個小時完成

• 0
  • 關閉時，須要完成全部full purge，insert buffer， flush dirty pages操做
  • 作 innodb plugin升級時，會設置爲0，再正常關閉數據庫。
• 1
  • 默認值，表示不須要完成full purge和insert buffer操做，可是緩衝池的髒數據須要刷新到磁盤
• 2
  • 既不完成full purge和insert buffer操做，也不把緩衝池的髒數據刷新到磁盤，而是將日誌寫入日誌文件，這樣不回有數據丟失，可是下次mysql啓動的時候，須要根據日誌文件執行恢復操做

2.2 恢復參數：innodb_force_recovery

    這裏注意，數字越小，則忽略檢查的內容越少，每一個大的數字都包含了前面小數字忽略檢查的內容。當參數設置大於0後，能夠對錶格進行DML操做，可是DDL操做時不容許的。

    當innodb_force_recovery 值爲1-3時，僅容許SELECT TABLE ，DROP or CREATE tables；innodb_force_recovery 值爲>=4時，5.7.17以前版本支持DROP TABLE，5.7.18後版本不支持。

    參數說明以下圖：

3 測試狀況

    測試內容：

    begin;insert into orders select * from orders.orders limit 100000;

    插入結束後不提交事務，執行 kill mysql進程

    tailf error.log查看

3.1 默認配置測試：innodb_fast_shutdown=1，innodb_force_recovery=0

   配置說明：異常中止DB服務時，不須要完成 full purge 和 insert buffer 操做，可是緩衝池的髒數據須要刷新到磁盤；服務啓動的時候，作全部須要的檢查跟事務操做。

3.1.1 操做過程

 1 #1 tailf error.log查看mysql錯誤日誌,動態滾動查看
 2 mysql> show global variables like 'log_error';
 3 tailf /data/mysql/mysql3310/data/error.log
 4 
 5 #2 測試庫中開啓事務，insert 10w行記錄，不提交事務
 6 mysql> begin;insert into orders select * from orders.orders limit 100000;
 7 Query OK, 0 rows affected (0.00 sec)
 8 
 9 Query OK, 100000 rows affected (37.55 sec)
10 Records: 100000  Duplicates: 0  Warnings: 0
11 
12 #3 查找mysql進程號，殺進程
13 [root@localhost opt]# ps axu | grep mysql
14 [root@localhost opt]# kill -9 mysql的進程號
15 
16 #4 啓動mysql服務
17 mysqld --defaults-file=/data/mysql/mysql3310/mysql3310.cnf &
18 
19 #5 到tailf error.log窗口查看錯誤

3.1.2 error log解析

啓動mysqld進程

2017-03-16T16:28:13.812074Z 0 [Note] mysqld (mysqld 5.7.14-log) starting as process 28091 ...

 

讀取ibdata的LSN

讀取redo文件的checkpoint，從該點的LSN開始查找MLOG_CHECKPOINT

發現MLOG_CHECKPOINT日誌，提示：Database was not shutdown normally !  

2017-03-16T16:28:16.572276Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 898634772645

2017-03-16T16:28:16.572418Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898634772654

2017-03-16T16:28:16.693771Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898634772654

2017-03-16T16:28:16.693880Z 0 [Note] InnoDB: Database was not shutdown normally!

2017-03-16T16:28:16.693913Z 0 [Note] InnoDB: Starting crash recovery.

 

檢測須要重作跟回滾的事務

因爲沒有須要redo的事務，可是有undo事務，開始undo操做

加載redo log中的96個系統回滾段 rollbak segment，32個不須要redo 的臨時表空間的回滾段

2017-03-16T16:28:17.360953Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 100000 row operations to undo

 

獲取binlog回滾xid列表，結合undo log作回滾操做

2017-03-16T16:28:17.361122Z 0 [Note] InnoDB: Trx id counter is 5716480

2017-03-16T16:28:17.625441Z 0 [Note] InnoDB: Last MySQL binlog file position 0 37774, file name bin_log.000016

2017-03-16T16:28:17.787684Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions

2017-03-16T16:28:17.788022Z 0 [Note] InnoDB: Rolling back trx with id 5715975, 100000 rows to undo

 

啓動innodb，加載buffer pool

2017-03-16T16:28:17.838323Z 0 [Note] InnoDB: Waiting for purge to start

2017-03-16T16:28:18.015792Z 0 [Note] InnoDB: 5.7.14 started; log sequence number 898634772654

 

mysqld正常運行提供用戶使用

2017-03-16T16:28:18.772035Z 0 [Note] mysqld: ready for connections.

Version: '5.7.14-log'  socket: '/tmp/mysql3310.sock'  port: 3310  MySQL Community Server (GPL)

 

這個時候，recovery可能還沒結束，好比這個例子中，recovery就還在進行，其涉及的表僅提供ReadOnly操做，其餘表格可正常操做 ，慢慢恢復，最後undo回滾事務完成，Rollback of non-prepared transactions completed

 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 1002017-03-16T16:29:24.353056Z 0 [Note] InnoDB: Rollback of trx with id 5715975 completed

2017-03-16T16:29:24.353267Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed

 

整個過程16:28:13啓動，16:28:18 DB提供部分服務，16:29:24全庫恢復，db部分提供服務耗時5s，全庫提供服務耗時71s 。

 1 2017-03-16T16:28:13.812074Z 0 [Note] mysqld (mysqld 5.7.14-log) starting as process 28091 ...
 2 2017-03-16T16:28:14.250956Z 0 [Note] InnoDB: PUNCH HOLE support not available
 3 2017-03-16T16:28:14.251212Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 4 2017-03-16T16:28:14.251311Z 0 [Note] InnoDB: Uses event mutexes
 5 2017-03-16T16:28:14.251359Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
 6 2017-03-16T16:28:14.251401Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
 7 2017-03-16T16:28:14.251311Z 0 [Note] InnoDB: Uses event mutexes
 8 2017-03-16T16:28:14.251359Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
 9 2017-03-16T16:28:14.251401Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
10 2017-03-16T16:28:14.251440Z 0 [Note] InnoDB: Using Linux native AIO
11 2017-03-16T16:28:14.252570Z 0 [Note] InnoDB: Number of pools: 1
12 2017-03-16T16:28:14.253079Z 0 [Note] InnoDB: Not using CPU crc32 instructions
13 2017-03-16T16:28:14.258163Z 0 [Note] InnoDB: Initializing buffer pool, total size = 9G, instances = 8, chunk size = 128M
14 2017-03-16T16:28:16.101862Z 0 [Note] InnoDB: Completed initialization of buffer pool
15 2017-03-16T16:28:16.406890Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
16 2017-03-16T16:28:16.447145Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
17 2017-03-16T16:28:16.572276Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 898634772645
18 2017-03-16T16:28:16.572418Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898634772654
19 2017-03-16T16:28:16.693771Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898634772654
20 2017-03-16T16:28:16.693880Z 0 [Note] InnoDB: Database was not shutdown normally!
21 2017-03-16T16:28:16.693913Z 0 [Note] InnoDB: Starting crash recovery.
22 2017-03-16T16:28:17.360953Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 100000 row operations to undo
23 2017-03-16T16:28:17.361122Z 0 [Note] InnoDB: Trx id counter is 5716480
24 2017-03-16T16:28:17.625441Z 0 [Note] InnoDB: Last MySQL binlog file position 0 37774, file name bin_log.000016
25 2017-03-16T16:28:17.787684Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
26 2017-03-16T16:28:17.788022Z 0 [Note] InnoDB: Rolling back trx with id 5715975, 100000 rows to undo
27 
28 InnoDB: Progress in percents: 12017-03-16T16:28:17.788272Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
29 2017-03-16T16:28:17.788603Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
30 2017-03-16T16:28:17.788603Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
31 2017-03-16T16:28:17.788937Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
32 2017-03-16T16:28:17.831078Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
33 2017-03-16T16:28:17.834673Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
34 2017-03-16T16:28:17.834822Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
35 2017-03-16T16:28:17.838323Z 0 [Note] InnoDB: Waiting for purge to start
36 2017-03-16T16:28:18.015792Z 0 [Note] InnoDB: 5.7.14 started; log sequence number 898634772654
37 2017-03-16T16:28:18.018091Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3310/data/ib_buffer_pool
38 2017-03-16T16:28:18.018464Z 0 [Note] Plugin 'FEDERATED' is disabled.
39 2017-03-16T16:28:18.119301Z 0 [Note] Recovering after a crash using /data/mysql/mysql3310/logs/bin_log
40 2017-03-16T16:28:18.119442Z 0 [Note] Starting crash recovery...
41 2017-03-16T16:28:18.119442Z 0 [Note] Starting crash recovery...
42 2017-03-16T16:28:18.119624Z 0 [Note] Crash recovery finished.
43 2017-03-16T16:28:18.203723Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
44 2017-03-16T16:28:18.203835Z 0 [Note] Server hostname (bind-address): '*'; port: 3310
45 2017-03-16T16:28:18.204188Z 0 [Note] IPv6 is available.
46 2017-03-16T16:28:18.204339Z 0 [Note]   - '::' resolves to '::';
47 2017-03-16T16:28:18.204667Z 0 [Note] Server socket created on IP: '::'.
48 2017-03-16T16:28:18.377789Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
49 2017-03-16T16:28:18.378054Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
50 2017-03-16T16:28:18.378170Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
51 2017-03-16T16:28:18.392680Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
52 2017-03-16T16:28:18.771122Z 0 [Note] Event Scheduler: Loaded 0 events
53 2017-03-16T16:28:18.772035Z 0 [Note] mysqld: ready for connections.
54 Version: '5.7.14-log'  socket: '/tmp/mysql3310.sock'  port: 3310  MySQL Community Server (GPL)
55 2017-03-16T16:28:21.404135Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170317  0:28:21
56  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 1002017-03-16T16:29:24.353056Z 0 [Note] InnoDB: Rollback of trx with id 5715975 completed
57 2017-03-16T16:29:24.353267Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed

實驗1 error log詳細內容

3.2 innodb_fast_shutdown=1，innodb_force_recovery=3

    配置說明：異常中止DB服務時，不須要完成full purge和insert buffer操做，可是緩衝池的髒數據須要刷新到磁盤；服務啓動的時候，忽略檢查corrupt頁，也阻止主線程的運行，而且不執行事務回滾操做。

    當innodb_force_recovery 值爲1-3時，容許SELECT TABLE ，DROP or CREATE tables；innodb_force_recovery 值爲>=4時，5.7.17以前版本支持DROP TABLE，5.7.18後版本不支持。

    這個配置適用於這種狀況：有某些大表執行alter或者大量數據修改操做生成大量undo宕機，那麼這個狀況下，能夠進入cnf配置文件修改innodb_force_recovery=3，而後把再作undo操做的表格數據導出來或者利用備份文件的數據，再drop掉這個表格，進入cnf配置文件，修改參數爲0，重啓DB服務，會發現，rollback過程很是快執行結束，由於找不到對應表格，因此rollback很是快。

 

    Tips: 如何查找在undo操做的表格？

    數據庫crash後，第一個正常啓動恢復鏈接，連進數據庫裏邊，操做全部表格，不支持insert update 的表格都屬於正在undo的表。

 

3.2.1 操做過程

 1 #1 tailf error.log查看mysql錯誤日誌,動態滾動查看
 2 mysql> show global variables like 'log_error';
 3 tailf /data/mysql/mysql3310/data/error.log
 4 
 5 #2 測試庫中開啓事務，insert 10w行記錄，不提交事務
 6 mysql> begin;insert into orders select * from orders.orders limit 100000;
 7 Query OK, 0 rows affected (0.00 sec)
 8 
 9 Query OK, 100000 rows affected (37.55 sec)
10 Records: 100000  Duplicates: 0  Warnings: 0
11 
12 #3 查找mysql進程號，殺進程
13 [root@localhost opt]# ps axu | grep mysql
14 [root@localhost opt]# kill -9 mysql的進程號
15 
16 #4 在cnf文件中指定innodb_force_recovery=3,啓動服務，檢查是否修改爲功
17 [root@localhost ~]# vim /data/mysql/mysql3310.cnf
18 #添加innodb_force_recovery參數設置
19 [mysqld]
20 innodb_force_recovery=3
21 
22 #5 啓動mysql服務
23 [root@localhost ~]# mysqld --defaults-file=/data/mysql/mysql3310.cnf &
24 
25 #6 到tailf error.log窗口查看錯誤
26 #發現沒有進行undo操做，同時全庫僅支持select drop create，不支持其餘全部操做

3.2.2 error log解析

啓動mysqld進程

2017-03-17T15:12:14.317391Z 0 [Note] mysqld (mysqld 5.7.14-log) starting as process 32094 ...

 

讀取ibdata的LSN

讀取redo文件的checkpoint，從該點的LSN開始查找MLOG_CHECKPOINT

發現MLOG_CHECKPOINT日誌，提示：Database was not shutdown normally !  

2017-03-17T15:12:16.478403Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 898935661420

2017-03-17T15:12:16.478579Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898935661429

2017-03-17T15:12:16.532923Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898935661429

2017-03-17T15:12:16.533063Z 0 [Note] InnoDB: Database was not shutdown normally!

2017-03-17T15:12:16.533105Z 0 [Note] InnoDB: Starting crash recovery.

 

檢測須要重作跟回滾的事務

因爲沒有須要redo的事務，可是有undo事務，開始undo操做

加載redo log中的96個系統回滾段 rollbak segment，32個不須要redo 的臨時表空間的回滾段

2017-03-17T15:12:17.052734Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 100000 row operations to undo

 

獲取binlog回滾xid列表，可是這裏注意，沒有作 回滾操做

2017-03-17T15:12:17.053009Z 0 [Note] InnoDB: Trx id counter is 5718016

2017-03-17T15:12:17.321987Z 0 [Note] InnoDB: Last MySQL binlog file position 0 37774, file name bin_log.000016

 

啓動innodb，加載buffer pool ，警告當前 innodb_force_recovery 設置爲3

2017-03-17T15:12:17.518732Z 0 [Note] InnoDB: 5.7.14 started; log sequence number 898935661429

2017-03-17T15:12:17.518789Z 0 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!

2017-03-17T15:12:17.519305Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3310/data/ib_buffer_pool

 

mysqld正常運行提供用戶使用，可是，全庫僅提供readonly

2017-03-17T15:12:18.521680Z 0 [Note] mysqld: ready for connections.

Version: '5.7.14-log'  socket: '/tmp/mysql3310.sock'  port: 3310  MySQL Community Server (GPL)

2017-03-17T15:13:03.125686Z 2 [ERROR] InnoDB: innodb_force_recovery is on. We do not allow database modifications by the user. Shut down mysqld and edit my.cnf to set innodb_force_recovery=0

 

    整個過程 15:12:14啓動，15:12:18 DB提供部分服務，耗時4s。可是因爲沒有作undo操做，錯誤日誌提醒 We do not allow database modifications by the user. 不支持當前用戶進行數據庫修改操做，僅支持select table，drop table，create table操做，其餘全部操做都不支持。

    這種狀況下啓動數據庫後，能夠支持你dump出正在作undo的表格數據，而後drop掉它，若是你有備份文件恢復，那麼則不須要dump，直接drop，而後修改cnf配置文件，設置 innodb_force_recovery=0 ，重啓數據庫服務，這個時候，innodb 的undo recovery很是快，由於找不到對應的表格操做，因此都是直接挑過處理。正常恢復後，趕忙把drop掉的表格從備份文件或者dump出來的sql文件中恢復回來。注意注意！！！！這種狀況要權衡利弊，從時間耗時跟操做安全數據安全考慮，是undo recovery快仍是你如此操做快，而後必定必定要跟你的上級或者領導報備操做的風險性，不要默默幹，要報告！！！

 1 2017-03-17T15:12:14.317391Z 0 [Note] mysqld (mysqld 5.7.14-log) starting as process 32094 ...
 2 2017-03-17T15:12:14.430101Z 0 [Note] InnoDB: PUNCH HOLE support not available
 3 2017-03-17T15:12:14.430586Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 4 2017-03-17T15:12:14.430732Z 0 [Note] InnoDB: Uses event mutexes
 5 2017-03-17T15:12:14.430874Z 0 [Note] InnoDB: GCC builtin __sync_synchronize() is used for memory barrier
 6 2017-03-17T15:12:14.430993Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
 7 2017-03-17T15:12:14.431084Z 0 [Note] InnoDB: Using Linux native AIO
 8 2017-03-17T15:12:14.433127Z 0 [Note] InnoDB: Number of pools: 1
 9 2017-03-17T15:12:14.434016Z 0 [Note] InnoDB: Not using CPU crc32 instructions
10 2017-03-17T15:12:14.443970Z 0 [Note] InnoDB: Initializing buffer pool, total size = 9G, instances = 8, chunk size = 128M
11 2017-03-17T15:12:16.158820Z 0 [Note] InnoDB: Completed initialization of buffer pool
12 2017-03-17T15:12:16.380118Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
13 2017-03-17T15:12:16.409819Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
14 2017-03-17T15:12:16.478403Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 898935661420
15 2017-03-17T15:12:16.478579Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898935661429
16 2017-03-17T15:12:16.532923Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 898935661429
17 2017-03-17T15:12:16.533063Z 0 [Note] InnoDB: Database was not shutdown normally!
18 2017-03-17T15:12:16.533105Z 0 [Note] InnoDB: Starting crash recovery.
19 2017-03-17T15:12:17.052734Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 100000 row operations to undo
20 2017-03-17T15:12:17.053009Z 0 [Note] InnoDB: Trx id counter is 5718016
21 2017-03-17T15:12:17.321987Z 0 [Note] InnoDB: Last MySQL binlog file position 0 37774, file name bin_log.000016
22 2017-03-17T15:12:17.460435Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
23 2017-03-17T15:12:17.460673Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
24 2017-03-17T15:12:17.461075Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
25 2017-03-17T15:12:17.512923Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
26 2017-03-17T15:12:17.516337Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
27 2017-03-17T15:12:17.516617Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
28 2017-03-17T15:12:17.518732Z 0 [Note] InnoDB: 5.7.14 started; log sequence number 898935661429
29 2017-03-17T15:12:17.518789Z 0 [Note] InnoDB: !!! innodb_force_recovery is set to 3 !!!
30 2017-03-17T15:12:17.519305Z 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mysql3310/data/ib_buffer_pool
31 2017-03-17T15:12:17.521217Z 0 [Note] Plugin 'FEDERATED' is disabled.
32 2017-03-17T15:12:17.694697Z 0 [Note] Recovering after a crash using /data/mysql/mysql3310/logs/bin_log
33 2017-03-17T15:12:17.694882Z 0 [Note] Starting crash recovery...
34 2017-03-17T15:12:17.695070Z 0 [Note] Crash recovery finished.
35 2017-03-17T15:12:18.197454Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key
36 2017-03-17T15:12:18.197584Z 0 [Note] Server hostname (bind-address): '*'; port: 3310
37 2017-03-17T15:12:18.197804Z 0 [Note] IPv6 is available.
38 2017-03-17T15:12:18.197910Z 0 [Note]   - '::' resolves to '::';
39 2017-03-17T15:12:18.197981Z 0 [Note] Server socket created on IP: '::'.
40 2017-03-17T15:12:18.391615Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170317 23:12:18
41 2017-03-17T15:12:18.414950Z 0 [Warning] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
42 2017-03-17T15:12:18.415223Z 0 [Warning] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
43 2017-03-17T15:12:18.415340Z 0 [Warning] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
44 2017-03-17T15:12:18.446935Z 0 [Warning] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
45 2017-03-17T15:12:18.520569Z 0 [Note] Event Scheduler: Loaded 0 events
46 2017-03-17T15:12:18.521680Z 0 [Note] mysqld: ready for connections.
47 Version: '5.7.14-log'  socket: '/tmp/mysql3310.sock'  port: 3310  MySQL Community Server (GPL)
48 2017-03-17T15:13:03.125686Z 2 [ERROR] InnoDB: innodb_force_recovery is on. We do not allow database modifications by the user. Shut down mysqld and edit my.cnf to set innodb_force_recovery=0

實驗2 詳細error log記錄

 

參考文章：

https://dev.mysql.com/doc/refman/5.7/en/innodb-parameters.html

http://www.sysdb.cn/index.php/2016/01/14/innodb-recovery/?utm_source=tuicool&utm_medium=referral

http://mysql.taobao.org/monthly/2015/06/01/