MySQL 磁碟空間滿導致表空間相關資料檔案損壞故障處理

近期，遇到一個mysql資料庫因為磁碟空間滿導致表空間相關資料檔案損壞而無法啟動，相關處理過程如下：

1、mysql資料庫磁碟空間滿報錯提示

2019-09-30T01:25:10.326653+08:00 22822601 [Note] Aborted connection 22822601 to db: 'unconnected' user: 'bpuser' host: 'localhost' (Got an error reading communication packets)

2019-09-30T01:25:12.893926+08:00 21573334 [ERROR] Disk is full writing '/data/mysql/mydata/blog/mysql-bin.002059' (Errcode: 15425568 - No space left on device). Waiting for someone to free space...

2019-09-30T01:25:12.893974+08:00 21573334 [ERROR] Retry in 60 secs. Message reprinted in 600 secs

2019-09-30T01:25:27.822078+08:00 0 [ERROR] [FATAL] InnoDB: Native Linux AIO interface. io_submit() call failed when resubmitting a partial I/O request on the file ./mydata/history_uint2019-09-30T01:25:28.811224+08:00 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled

2、mysql重啟失敗報錯提示

2019-09-30T01:25:35.462390+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947029007360

2019-09-30T01:25:35.683704+08:00 0 [ERROR] InnoDB: Space ID in fsp header is 4275156, but in the page header it is 164.

2019-09-30T01:25:35.683774+08:00 0 [ERROR] InnoDB: Header page contains inconsistent data in datafile: ./mydata/history_uint#P#p201910130000.ibd, Space ID:18446744073709551615, Flags: 17039360. Please refer to http://dev.mysql.com/doc/refman/5.7/en/innodb-troubleshooting-datadict.html for how to resolve the issue.

2019-09-30T01:25:35.683865+08:00 0 [Note] InnoDB: Page size:1024. Pages to analyze:64

......

2019-09-30T01:25:35.689292+08:00 0 [Note] InnoDB: Chosen space:164

2019-09-30T01:25:35.689327+08:00 0 [ERROR] InnoDB: Corrupted page [page id: space=164, page number=0] of datafile './mydata/his_uint#P#p201910130000.ibd' could not be found in the doublewrite buffer.

......

2019-09-30T01:25:50.175443+08:00 0 [Note] InnoDB: Starting crash recovery.

2019-09-30T01:25:50.462341+08:00 0 [ERROR] InnoDB: Tablespace 431 was not found at ./mydata/his_uint#P#p201910130000.ibd.

2019-09-30T01:25:50.462391+08:00 0 [ERROR] InnoDB: Set innodb_force_recovery=1 to ignore this and to permanently lose all changes to the tablespace.

2019-09-30T01:25:50.481016+08:00 0 [ERROR] InnoDB: Cannot continue operation.

2019-09-30T01:28:44.666477Z mysqld_safe Logging to '/data/mysql/mydata/errlog/mysql.err'.

2019-09-30T01:28:44.736202Z mysqld_safe Starting mysqld daemon with databases from /data/mysql/mydata/data

3、安裝mysql報錯日誌提示

在引數檔案中加入：innodb_force_recovery=1 重新啟動資料庫，注意此引數是讓資料庫引擎忽略崩潰的事務或者資料塊，會丟失資料。

2019-09-30T14:59:29.161408+08:00 0 [Note] InnoDB: At LSN: 1947033396675: unable to open file ./mydata/history_uint#P#p201907310000.ibd for tablespace 357

2019-09-30T14:59:29.173311+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947034250240

2019-09-30T14:59:29.391928+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947039493120

2019-09-30T14:59:29.619846+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947044736000

2019-09-30T14:59:29.883131+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947049978880

2019-09-30T14:59:30.150950+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947055221760

2019-09-30T14:59:30.412127+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947060464640

2019-09-30T14:59:30.682865+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947065707520

2019-09-30T14:59:30.946472+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947070950400

2019-09-30T14:59:31.208800+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947076193280

2019-09-30T14:59:31.488423+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947081436160

2019-09-30T14:59:31.769203+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947086679040

2019-09-30T14:59:32.046024+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947091921920

2019-09-30T14:59:32.323284+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947097164800

2019-09-30T14:59:32.602593+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947102407680

2019-09-30T14:59:32.879621+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947107650560

2019-09-30T14:59:33.162674+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947112893440

2019-09-30T14:59:33.443923+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947118136320

2019-09-30T14:59:33.722263+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947123379200

2019-09-30T14:59:34.005038+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947128622080

2019-09-30T14:59:34.277561+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947133864960

2019-09-30T14:59:34.553648+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947139107840

2019-09-30T14:59:34.837634+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947144350720

2019-09-30T14:59:35.126704+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947149593600

2019-09-30T14:59:35.405475+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947154836480

2019-09-30T14:59:35.677461+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947160079360

2019-09-30T14:59:35.955224+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947165322240

2019-09-30T14:59:36.234978+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947170565120

2019-09-30T14:59:36.507701+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947175808000

2019-09-30T14:59:36.787124+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947181050880

2019-09-30T14:59:37.072707+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947186293760

2019-09-30T14:59:37.352348+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947191536640

2019-09-30T14:59:37.553603+08:00 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 1947195379409

2019-09-30T14:59:37.554826+08:00 0 [Note] InnoDB: Database was not shutdown normally!

2019-09-30T14:59:37.554862+08:00 0 [Note] InnoDB: Starting crash recovery.

2019-09-30T14:59:37.639990+08:00 0 [Warning] InnoDB: Tablespace 431 was not found at ./mydata/his_uint#P#p201910130000.ibd, and innodb_force_recovery was set. All redo log for this tablespace will be ignored!

2019-09-30T14:59:38.718448+08:00 0 [Note] InnoDB: Transaction 439021218 was in the XA prepared state.

2019-09-30T14:59:38.718568+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.721677+08:00 0 [Note] InnoDB: Transaction 439021219 was in the XA prepared state.

2019-09-30T14:59:38.721715+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.721742+08:00 0 [Note] InnoDB: Transaction 439021220 was in the XA prepared state.

2019-09-30T14:59:38.721755+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.721785+08:00 0 [Note] InnoDB: Transaction 439021221 was in the XA prepared state.

2019-09-30T14:59:38.721801+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.721932+08:00 0 [Note] InnoDB: Transaction 439021222 was in the XA prepared state.

2019-09-30T14:59:38.721957+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.721976+08:00 0 [Note] InnoDB: Transaction 439021223 was in the XA prepared state.

2019-09-30T14:59:38.721990+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.722051+08:00 0 [Note] InnoDB: Transaction 439021224 was in the XA prepared state.

2019-09-30T14:59:38.722094+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.722122+08:00 0 [Note] InnoDB: Transaction 439021225 was in the XA prepared state.

2019-09-30T14:59:38.722171+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.722285+08:00 0 [Note] InnoDB: Transaction 439021226 was in the XA prepared state.

2019-09-30T14:59:38.722308+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.722337+08:00 0 [Note] InnoDB: Transaction 439021227 was in the XA prepared state.

2019-09-30T14:59:38.722354+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.722374+08:00 0 [Note] InnoDB: Transaction 439021228 was in the XA prepared state.

2019-09-30T14:59:38.722385+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will force a rollback.

2019-09-30T14:59:38.722416+08:00 0 [Note] InnoDB: Transaction 439021229 was in the XA prepared state.

2019-09-30T14:59:38.722429+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.891187+08:00 0 [Note] InnoDB: Transaction 439021230 was in the XA prepared state.

2019-09-30T14:59:38.891241+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.891272+08:00 0 [Note] InnoDB: Transaction 439021231 was in the XA prepared state.

2019-09-30T14:59:38.891294+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.891349+08:00 0 [Note] InnoDB: Transaction 439021232 was in the XA prepared state.

2019-09-30T14:59:38.891372+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.951935+08:00 0 [Note] InnoDB: Transaction 439021233 was in the XA prepared state.

2019-09-30T14:59:38.951987+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.952095+08:00 0 [Note] InnoDB: Transaction 439021234 was in the XA prepared state.

2019-09-30T14:59:38.952118+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.952211+08:00 0 [Note] InnoDB: Transaction 439021235 was in the XA prepared state.

2019-09-30T14:59:38.952231+08:00 0 [Note] InnoDB: Since innodb_force_recovery > 0, we will rollback it anyway.

2019-09-30T14:59:38.952274+08:00 0 [Note] InnoDB: 18 transaction(s) which must be rolled back or cleaned up in total 1320 row operations to undo

2019-09-30T14:59:38.952292+08:00 0 [Note] InnoDB: Trx id counter is 439021568

2019-09-30T14:59:38.952422+08:00 0 [Note] InnoDB: Starting an apply batch of log records to the database...

InnoDB: Progress in percent: 0 1 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 

2019-09-30T14:59:55.205973+08:00 0 [Note] InnoDB: Apply batch completed

2019-09-30T14:59:55.206099+08:00 0 [Note] InnoDB: Last MySQL binlog file position 0 220761212, file name mysql-bin.002059

2019-09-30T14:59:55.353727+08:00 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions

2019-09-30T14:59:55.353918+08:00 0 [Note] InnoDB: Rolling back trx with id 439021235, 1 rows to undo

2019-09-30T14:59:55.355905+08:00 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

2019-09-30T14:59:55.355970+08:00 0 [Note] InnoDB: Creating shared tablespace for temporary tables

2019-09-30T14:59:55.356072+08:00 0 [Note] InnoDB: Setting file '/data/mysql/mydata/data/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...

2019-09-30T14:59:55.360842+08:00 0 [Note] InnoDB: File '/data/mysql/mydata/data/ibtmp1' size is now 12 MB.

2019-09-30T14:59:55.362952+08:00 0 [Note] InnoDB: Rollback of trx with id 439021235 completed

2019-09-30T14:59:55.363004+08:00 0 [Note] InnoDB: Rolling back trx with id 439021234, 1 rows to undo

2019-09-30T14:59:55.364047+08:00 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.

2019-09-30T14:59:55.364097+08:00 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.

2019-09-30T14:59:55.364756+08:00 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 28917ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)

2019-09-30T14:59:55.364864+08:00 0 [Note] InnoDB: 5.7.21 started; log sequence number 1947195379409

2019-09-30T14:59:55.364942+08:00 0 [Note] InnoDB: !!! innodb_force_recovery is set to 2 !!!

2019-09-30T14:59:55.365252+08:00 0 [Note] InnoDB: Loading buffer pool(s) from /data/mysql/mydata/data/ib_buffer_pool

2019-09-30T14:59:55.365982+08:00 0 [Note] Plugin 'FEDERATED' is disabled.

2019-09-30T14:59:55.374150+08:00 0 [Note] InnoDB: Rollback of trx with id 439021234 completed

2019-09-30T14:59:55.374211+08:00 0 [Note] InnoDB: Rolling back trx with id 439021233, 1 rows to undo

2019-09-30T14:59:55.374303+08:00 0 [Note] InnoDB: Rollback of trx with id 439021233 completed

2019-09-30T14:59:55.374353+08:00 0 [Note] InnoDB: Rolling back trx with id 439021232, 2 rows to undo

2019-09-30T14:59:55.385121+08:00 0 [Note] InnoDB: Rollback of trx with id 439021232 completed

2019-09-30T14:59:55.385173+08:00 0 [Note] InnoDB: Rolling back trx with id 439021231, 4 rows to undo

2019-09-30T14:59:55.385291+08:00 0 [Note] InnoDB: Rollback of trx with id 439021231 completed

2019-09-30T14:59:55.385329+08:00 0 [Note] InnoDB: Rolling back trx with id 439021230, 1 rows to undo

2019-09-30T14:59:55.385430+08:00 0 [Note] InnoDB: Rollback of trx with id 439021230 completed

2019-09-30T14:59:55.385465+08:00 0 [Note] InnoDB: Rolling back trx with id 439021229, 1 rows to undo

2019-09-30T14:59:55.385596+08:00 0 [Note] InnoDB: Rollback of trx with id 439021229 completed

2019-09-30T14:59:55.385634+08:00 0 [Note] InnoDB: Rolling back trx with id 439021228, 288 rows to undo

2019-09-30T14:59:55.419044+08:00 0 [Note] Semi-sync replication initialized for transactions.

2019-09-30T14:59:55.419087+08:00 0 [Note] Semi-sync replication enabled on the master.

2019-09-30T14:59:55.420374+08:00 0 [Note] Starting ack receiver thread

2019-09-30T14:59:55.443313+08:00 0 [Note] Recovering after a crash using /data/mysql/mydata/blog/mysql-bin

2019-09-30T14:59:55.989634+08:00 0 [Note] InnoDB: Rollback of trx with id 439021228 completed

2019-09-30T14:59:55.989688+08:00 0 [Note] InnoDB: Rolling back trx with id 439021227, 33 rows to undo

2019-09-30T14:59:56.031958+08:00 0 [Note] InnoDB: Rollback of trx with id 439021227 completed

2019-09-30T14:59:56.032008+08:00 0 [Note] InnoDB: Rolling back trx with id 439021226, 122 rows to undo

2019-09-30T14:59:56.206430+08:00 0 [Note] InnoDB: Rollback of trx with id 439021226 completed

2019-09-30T14:59:56.206608+08:00 0 [Note] InnoDB: Rolling back trx with id 439021225, 6 rows to undo

2019-09-30T14:59:56.206979+08:00 0 [Note] InnoDB: Rollback of trx with id 439021225 completed

2019-09-30T14:59:56.207023+08:00 0 [Note] InnoDB: Rolling back trx with id 439021224, 3 rows to undo

2019-09-30T14:59:56.207246+08:00 0 [Note] InnoDB: Rollback of trx with id 439021224 completed

2019-09-30T14:59:56.207275+08:00 0 [Note] InnoDB: Rolling back trx with id 439021223, 31 rows to undo

2019-09-30T14:59:56.253734+08:00 0 [Note] InnoDB: Rollback of trx with id 439021223 completed

2019-09-30T14:59:56.253781+08:00 0 [Note] InnoDB: Rolling back trx with id 439021222, 1 rows to undo

2019-09-30T14:59:56.253885+08:00 0 [Note] InnoDB: Rollback of trx with id 439021222 completed

2019-09-30T14:59:56.253940+08:00 0 [Note] InnoDB: Rolling back trx with id 439021221, 340 rows to undo

2019-09-30T14:59:56.261028+08:00 0 [ERROR] Error in Log_event::read_log_event(): 'read error', data_len: 1103, event_type: 29

2019-09-30T14:59:56.261118+08:00 0 [Note] Starting crash recovery...

2019-09-30T14:59:56.261182+08:00 0 [Note] Crash recovery finished.

2019-09-30T14:59:56.261336+08:00 0 [Note] Crashed binlog file /data/mysql/mydata/blog/mysql-bin.002059 size is 220762112, but recovered up to 220761212. Binlog trimmed to 220761212 bytes.

2019-09-30T14:59:56.747437+08:00 0 [Note] InnoDB: Rollback of trx with id 439021221 completed

2019-09-30T14:59:56.747493+08:00 0 [Note] InnoDB: Rolling back trx with id 439021220, 169 rows to undo

2019-09-30T14:59:57.105815+08:00 0 [Note] InnoDB: Rollback of trx with id 439021220 completed

2019-09-30T14:59:57.105928+08:00 0 [Note] InnoDB: Rolling back trx with id 439021219, 35 rows to undo

2019-09-30T14:59:57.156088+08:00 0 [Note] InnoDB: Rollback of trx with id 439021219 completed

2019-09-30T14:59:57.156133+08:00 0 [Note] InnoDB: Rolling back trx with id 439021218, 281 rows to undo

2019-09-30T14:59:57.345363+08:00 0 [Note] InnoDB: Rollback of trx with id 439021218 completed

2019-09-30T14:59:57.345408+08:00 0 [Note] InnoDB: Rollback of non-prepared transactions completed

2019-09-30T14:59:57.790483+08:00 0 [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

mysqld: Operation not allowed when innodb_forced_recovery > 0.

2019-09-30T14:59:57.790649+08:00 0 [ERROR] Aborting

4、根據提示將innodb_forced_recovery設定為0，重新啟動資料庫成功

2019-09-30T15:20:29.097172+08:00 0 [Note] Semi-sync replication enabled on the master.

2019-09-30T15:20:29.097330+08:00 0 [Note] Starting ack receiver thread

2019-09-30T15:20:29.126933+08:00 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key

2019-09-30T15:20:29.126992+08:00 0 [Note] Server hostname (bind-address): '*'; port: 3306

2019-09-30T15:20:29.127081+08:00 0 [Note] IPv6 is available.

2019-09-30T15:20:29.127120+08:00 0 [Note]   - '::' resolves to '::';

2019-09-30T15:20:29.127160+08:00 0 [Note] Server socket created on IP: '::'.

5、關於innodb_forced_recovery擴充套件

innodb_force_recovery可以設定為1-6,大的數字包含前面所有數字的影響。

當設定引數值大於0後，可以對錶進行select,create,drop操作,

但insert,update或者delete這類操作是不允許的。

1(SRV_FORCE_IGNORE_CORRUPT):忽略檢查到的corrupt頁。

2(SRV_FORCE_NO_BACKGROUND):阻止主執行緒的執行，如主執行緒需要執行full purge操作，會導致crash。

3(SRV_FORCE_NO_TRX_UNDO):不執行事務回滾操作。

4(SRV_FORCE_NO_IBUF_MERGE):不執行插入緩衝的合併操作。

5(SRV_FORCE_NO_UNDO_LOG_SCAN):不檢視重做日誌，InnoDB儲存引擎會將未提交的事務視為已提交。

6(SRV_FORCE_NO_LOG_REDO):不執行前滾的操作。