天天看點
傳回

MySQL-記一次備份失敗的排查過程

MySQL-記一次備份失敗的排查過程

  山竹來臨，窩在家裡整理個人文檔。

       本篇文章主要講解排查問題的思路，涉及linux 删除檔案的原理、執行個體誤删資料恢複、MySQL執行個體初始化參數優先級别等，雖然涉及知識點比較淺，但是個人覺得挺有意思的，是以翻出筆記釋出出來。

    如果轉載，請注明博文來源： www.cnblogs.com/xinysu/   ，版權歸 部落格園 蘇家小蘿蔔 所有。望各位支援！

 1 備份出錯咯

    測試環境測試 xtrabackup 相關性能的時候，備份失敗！

    備份指令如下：

1 innobackupex --defaults-file=/apps/conf/mysql/mysql5_3306.cnf --socket=/tmp/mysql3306.sock --user=[*]--password=[*] --no-timestamp /apps/mysql_backup/test_backup_1 > /apps/mysql_backup/backup.log 2>&1

    備份錯誤日志如下：

xtrabackup: The latest check point (for incremental): '1209962'
xtrabackup: Stopping log copying thread.
.xtrabackup: warning: Log block checksum mismatch (block no 2364 at lsn 1209856):
expected 1161267116, calculated checksum 1312610971
xtrabackup: warning: this is possible when the log block has not been fully written by the server, will retry later.
180912 15:30:11 >> log scanned up to (1209856)
 
180912 15:30:11 Executing UNLOCK TABLES
180912 15:30:11 All tables unlocked
180912 15:30:11 Backup created in directory '/apps/mysql_backup/test_backup_1/'
MySQL binlog position: filename 'mysql-bin.000001', position '26708128'
180912 15:30:11 [00] Writing /apps/mysql_backup/test_backup_1/backup-my.cnf
180912 15:30:11 [00]        ...done
180912 15:30:11 [00] Writing /apps/mysql_backup/test_backup_1/xtrabackup_info
180912 15:30:11 [00]        ...done
xtrabackup: Transaction log of lsn (1209962) to (1209856) was copied.
xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856).

    Tips：

     資料庫執行個體運作正常的情況，在各個log buffer中，會存有 各個LSN，可以通過 show engine innodb status 檢視，但是注意，這個lsn并非是直接從磁盤檔案擷取，而是從buffer 中擷取。說明如下：

dba@localhost : (none) 17:00:21> show engine innodb status \G
......
---
LOG
---
Log sequence number 4158179984
Log flushed up to   4158179984
Pages flushed up to 4158179984
Last checkpoint at  4158179975
0 pending log flushes, 0 pending chkp writes
128445 log i/o's done, 0.00 log i/o's/second
......

# Log sequence number: 目前系統最大的LSN号
# log flushed up to: 目前已經寫入redo日志檔案的LSN
# pages flushed up to：已經将更改寫入髒頁的lsn号
# Last checkpoint at：系統最後一次重新整理buffer pool髒中頁資料到磁盤的checkpoint

# LSN1 = Log sequence number
# LSN2 = log flushed up to
# LSN3 = pages flushed up to
# LSN4 = Last checkpoint at
# LSN1 >= LSN2 >= LSN3 >= LSN4

2 備份錯誤解讀   

    xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856).

    說明xtrabckup 同步 redo log 到完成的時候，自身的 redo log 最後的 lsn 跟 目前資料庫的 ib_logfile檔案最後的 lsn對比，發現不比對。

    先檢查備份失敗執行個體内的 ib_logfile 檔案：

MySQL-記一次備份失敗的排查過程

    正常 ib_logfile 檔案的change time 應該是跟資料庫的初始化時間一緻，因為沒有修改 檔案的權限，但是顯示的change time 明顯晚與執行個體的運作時間，懷疑是否這幾個ib_logfile[*] 檔案被覆寫！

    為驗證ib_logfile[*] 檔案被覆寫，檢查 mysql 程序下是否有 deleted 句柄，截圖如下，發現 ib_logfile[*]檔案确實被覆寫。

MySQL-記一次備份失敗的排查過程

3 排查問題

哇，原來 檔案被删除，這裡有幾個疑問 ：

  1. 為何檔案被删除，不影響3306 執行個體 mysqld 的運作，3306 仍支援正常的 dml及ddl操作？
  2. 306的redo log 是寫入到哪些地方？
  3. 3306執行個體丢失的檔案能否恢複，能否正常使用？
  4. 為何 隻有 redo log 檔案被删除，是什麼操作導緻？

3.1 檔案被删，執行個體為何能正常運作

        在linux中，每個檔案都有兩個 link 計數器：

  • i_count：檔案使用者或者被調用的數量，了解為記憶體引用的計數器。檔案被程序打開使用的時候，自增+1。
  • i_nlink：硬連結的數量，了解為磁盤引用計數器。建立檔案的硬連結的時候，自增+1。

        當我們執行rm操作的時候，實際是 i_nlink-1，不一定真正删除檔案，隻有當 i_nlink=0 & i_count=0 時，檔案才會被真正删除。案例中的 ib_logfile[*] 由于沒有新建立硬連結，是以 i_nlink = 1，加上此時 3306執行個體處于運作中，需要調用 到 ib_logfile[*]檔案，是以 i_count = 1( 目前無其他程序使用到ib_logfile[*] )，當檔案被删除的時候，i_nlink =0 但是 i_count=0，故檔案不會被真正删除，僅删除 inode 連接配接，并沒有删除 磁盤的資料塊。

        那麼被程序調用的檔案，遭遇 rm 操作，那麼它将何去何從呢？

        首先，該檔案的 i_nlink被删除，剩下 i_count，故僅删除磁盤硬連結，内容未删除。可以通過 proc 檔案系統查找檔案。每個程序都有程序id，可以通過 proc檔案系統查找到該程序打開及調用的檔案的連結。

 測試1：在運作的新執行個體 3006 上，删除3個檔案後檢查

MySQL-記一次備份失敗的排查過程

3.2 資料實際寫入到哪裡，原被覆寫檔案？proc檔案系統檔案？

    測試2：删除表格檔案，檢視句柄size是否變化？

    測試内容：删除ib_logfile0檔案及tbb.ibd檔案，往 tbb 表格插入資料，檢視 ib_logfile0大小及tbb.ibd大小

    測試說明：為何是檢視大小，而不是檢視change time呢？因為node連結存儲了檔案的屬性，删除了該連結，則無法檢視檔案屬性，僅能通過lsof檢視檔案大小來判斷寫入情況。/proc檔案系統中的  deleted 軟連接配接，stat檢視也是檢視軟連接配接的屬性，并非 真實檔案資料塊。無論是root還是其他使用者删除，這個檔案都能寫入。

    測試過程：見截圖

    測試結果：因為ib_logfile 是固定大小1G，無法檢視到change時間，故不能驗證；但是可以從 tbb.ibd 檔案大小得知，實際是 redo log 是寫入到 被删除的檔案的。

MySQL-記一次備份失敗的排查過程

3.3 恢複被删除執行個體資料檔案

  1. 若是主庫檔案被删
    • 檢查從庫是否正常、是否無删除檔案
      1. 從庫正常
        1. 方案1
          1. 主從切換
          2. 舊主上，根據deleted句柄重定向被删除的資料塊到原先的磁盤位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
        2. 方案 2
          1. 重做 舊主庫，重做後恢複從庫使用
      2. 從庫不正常，檔案也被删
        1. 從庫，停止複制
        2. 從庫，根據deleted句柄重定向被删除的資料塊到原先的磁盤位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
        3. 從庫，恢複複制
        4. 檢查從庫追上主庫
        6. 舊主新從，停止複制，重定向檔案内容 或者重做 從庫
  2. 若是從庫檔案被删
      1. 從庫停止複制
      2. 從庫上，根據deleted句柄重定向被删除的資料塊到原先的磁盤位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
    2. 方案2

3.4 為何僅ib_logfile[*]檔案被删除，為何被删

    檢視 mysql 3306 的error 看看有啥苗頭：

180912 15:09:51 [Note] Plugin 'FEDERATED' is disabled.
180912 15:09:51 InnoDB: The InnoDB memory heap is disabled
180912 15:09:51 InnoDB: Mutexes and rw_locks use GCC atomic builtins
180912 15:09:51 InnoDB: Compressed tables use zlib 1.2.3
180912 15:09:51 InnoDB: Using Linux native AIO
180912 15:09:51 InnoDB: Initializing buffer pool, size = 1.0G
180912 15:09:51 InnoDB: Completed initialization of buffer pool
InnoDB: The first specified data file /apps/dbdat/mysql5_data3306/ibdata1 did not exist:
InnoDB: a new database to be created!
180912 15:09:51  InnoDB: Setting file /apps/dbdat/mysql5_data3306/ibdata1 size to 1000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
180912 15:09:55  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile0 did not exist: new to be created
InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile0 size to 1000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
180912 15:09:58  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile1 did not exist: new to be created
InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile1 size to 1000 MB
InnoDB: Database physically writes the file full: wait...
InnoDB: Progress in MB: 100 200 300 400 500 600 700 800 900 1000
180912 15:10:01  InnoDB: Log file /apps/dbdat/mysql5_data3306/ib_logfile2 did not exist: new to be created
InnoDB: Setting log file /apps/dbdat/mysql5_data3306/ib_logfile2 size to 1000 MB

    看log，是 建立執行個體的時候，覆寫了 3306執行個體的 ib_logfile跟ibdata1，但是實際上為何隻有 ib_logfile被覆寫呢？檢視曆史 操作指令，找到了 初始化 執行個體的指令如下：

history | grep mysql 

  368  /apps/svr/mysql57/bin/mysqld  --initialize  --datadir=/apps/dbdat/mysql57_data3307 --user=apps --innodb-data-file-path=ibdata1:1000M:autoextend --innodb-data-home-dir=/apps/dbdat/mysql57_data3307 --innodb-log-file-size=1000M --innodb-log-files-in-group=4 

3.5 為何使用指令指定參數執行建立執行個體，會覆寫其他執行個體的的檔案呢？

    檢視history 操作時，發現 之前執行了了 初始化執行個體的指令，沒有指定 配置檔案，而是指定了 datadir，另起伺服器，執行該指令，是正常，截圖如下，那麼這裡又 引申了 第五個 問題：為何使用 指令執行建立執行個體，會覆寫其他執行個體的的檔案呢？

MySQL-記一次備份失敗的排查過程

    靈機一動的我，聯想到了配置檔案的預設讀取順序，mysql安裝的時候，讀取配置檔案的優先順序：https://dev.mysql.com/doc/refman/5.7/en/option-files.html 。檢視 /etc/my.cnf ，發現确實是 有檔案存在，并且這個檔案是 3306的配置檔案内容。

File Name Purpose
/etc/my.cnf m
/etc/mysql/my.cnf Global options
SYSCONFDIR/my.cnf
$MYSQL_HOME/my.cnf Server-specific options (server only)
defaults-extra-file The file specified with --defaults-extra-file, if any
~/.my.cnf User-specific options
~/.mylogin.cnf User-specific login path options (clients only)

    這個時候，可以初步确認，mysql 3307 初始化的時候，除了使用 指定的指令外，其他需要的啟動參數會從 預設的配置檔案路徑依次讀取。那麼，mysql 初始化需要讀取哪些 必備參數呢 ？

    mysql 5.7 ，無預設配置檔案，僅指定參數 datadir basedir 初始化後生成 :mysql\sys\performance_schema 3個資料庫目錄及表格檔案，同時生成 ibdata1、ib_logfile[*]等檔案，是否可以判斷，初始化過程中，需要指定跟 ibdata1、ib_logfile【*】相關參數、error log位置、user 則正常呢？

 /apps/svr/mysql57/bin/mysqld  --initialize  --datadir=/apps/dbdat/mysql57_data3307 --user=apps --innodb-data-file-path=ibdata1:1000M:autoextend --innodb-data-home-dir=/apps/dbdat/mysql57_data3307 --innodb-log-file-size=1000M --innodb-log-files-in-group=4 --basedir=/apps/svr/mysql57 --innodb_log_group_home_dir=/apps/dbdat/mysql57_data3307  --innodb-log-files-in-group=4 --log-error=/apps/logs/mysql/error3307.log

    你以為這樣，就可以安裝了嗎？

    并不，當存在預設路徑的配置檔案時，除了指定參數外，還是會去讀 預設路徑 上的配置檔案 為主。

TIPS：

    模拟的過程中，一直無法重制這個錯誤，最後發現，沒有覆寫檔案，是因為：當 配置檔案的權限為所有人可寫的情況下，mysql擔心該配置檔案被惡意修改，故會忽略該檔案，不讀該檔案配置。

mysqld: [Warning] World-writable config file '/etc/my.cnf' is ignored.

4 錯誤原因總結

    綜上分析，則可以确定 3306執行個體正常運作期間，某位小夥伴 使用 指令初始化 3307執行個體，由于未指定 innodb_log_group_home_dir，mysql引擎去預設路徑下查找配置檔案，恰巧 /etc/my.cnf 是 3306執行個體的配置檔案，故 3307執行個體初始化的 innodb_log_group_home_dir 指向了 3306 執行個體，覆寫了 3306 執行個體的 ib_logfile[*] 檔案。

    那為何xtrabackup為何會報錯 xtrabackup: error: last checkpoint LSN (1209962) is larger than last copied LSN (1209856)？

這是因為 3307 執行個體初始化的過程中，讀取 /etc/my.cnf 配置檔案的時候，5.7版本已經沒有innodb_additional_mem_pool_size參數，故初始化到這裡的時候，報錯

2018-09-12T07:26:06.003983Z 0 [ERROR] unknown variable 'innodb_additional_mem_pool_size=32m'

2018-09-12T07:26:06.004004Z 0 [ERROR] Aborting

2018-09-12T07:26:06.004192Z 0 [Note] Binlog end

2018-09-12T07:26:06.010705Z 0 [Note] InnoDB: FTS optimize thread exiting.

2018-09-12T07:26:06.010917Z 0 [Note] InnoDB: Starting shutdown...

2018-09-12T07:26:06.111107Z 0 [Note] InnoDB: Dumping buffer pool(s) to /apps/dbdat/mysql57_data3307/ib_buffer_pool

2018-09-12T07:26:06.111312Z 0 [Note] InnoDB: Buffer pool(s) dump completed at 180912 15:26:06

2018-09-12T07:26:07.849696Z 0 [Note] InnoDB: Shutdown completed; log sequence number 1209962

2018-09-12T07:26:07.849933Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"

    實際上，如果是 5.7執行個體讀取 5.7配置檔案去 覆寫 5.7的舊執行個體，實際上備份并不會報錯，并且備份檔案在還原使用的時候也無異常，但是有一個緻命的問題，則是 備份過程中無法感覺執行個體的redo log變化，故并無跟進整個執行個體的redo log，導緻備份生成的xtrabckup_binlog_info 檔案中的binlog + postion 位置點是錯誤的，如果使用該備份來做從庫，則會出現嚴重缺失資料！！

    新伺服器上做測試如下：

  1. 初始化 5.7版本的3306執行個體，生成一張大表
  2. 拷貝 5.7 3306 執行個體的配置檔案到 /etc/my.cnf
  3. 指定參數初始化 3307執行個體
  4. 确認 3306 執行個體的 ib_logfile 被覆寫，但 3306 執行個體可以正常執行操作
  5. 備份 3306 執行個體正常，執行備份期間無錯誤
  6. 備份 3306執行個體期間，等待其拷貝完某張空表 tb.ibd 檔案後，迅速 insert 這張表 5000 行資料
  7. 進行還原操作，驗證備份是否有效
    1. 檢查 tb.ibd 檔案大小 為幾十kb
    2. 檢查 備份檔案夾中的 xtrabackup_logfile , 該檔案僅為 2.5k，并未記錄 insert tb.ibd檔案的操作
    3. apply log 後啟動檔案，發現tb.ibd 仍然為空表
  8. 結論
    1. 同版本覆寫的情況下
    2. 備份還原均無報錯資訊，但是其實是無效的，但是備份的  xtrabackup_binlog_info 記錄的log 、pos 與實際不相符
    3. 因為在做資料操作的時候，ib_logfile 沒有變動，故xtrabackup_logfile 檔案，并沒有記錄到實際的redo log，是以其 xtrabackup_binlog_info 記錄的log 跟pos 與實際不相符

5 處理流程總結

  1. 備份失敗
    1. 失敗原因：ib_logfile被覆寫
  2. 引發問題
    1. 運作中的db執行個體，檔案被覆寫，為何可正常運作？
      • linux 删除檔案原理，rm 被程序使用的檔案，僅删除 i_nlink，未删除實際資料塊，可從proc檔案系統查找
    2. 當檔案被覆寫後，還會繼續寫入 程序的修改資料嗎？
      • 寫入到 proc 指向的資料塊中，正常讀寫
    3. 如何恢複被覆寫的檔案？
      • 確定無資料寫入proc 指向的 deleted檔案，cat 重定向（注意耗時）
  3. 查找檔案被覆寫的原因
      1. 為何隻有 ib_logfile[*]被覆寫？
        1. 初始化僅指定部分參數，指定參數優先級别最高，其他讀取預設配置檔案參數，因為指定了 innodb-data-file-path、datadir，沒有指定 innodb_log_group_home_dir，故僅覆寫 ib_logfile[*]
      2. mysql初始化 指定參數 跟 預設路徑配置檔案的優先級 ？
        1. 優先級别高低
          1. 使用者指定參數
          2. 預設路徑配置檔案參數，按照預設路徑排序，屬性是 global 的，靠前的優先級别底，越後越高
          3. mysqld 預設參數值
      3. 為何某些情況下配置了/etc/my.cnf，但是不讀取？
        1. 當 配置檔案的權限為所有人可寫的情況下，mysql擔心該配置檔案被惡意修改，故會忽略該檔案，不讀該檔案配置
        3. 注意檢視 配置檔案權限 不是 777 權限

6 思考與改進

關于部署，使用defaults-file指定部署

關于恢複，注意主從處理及readonly 處理，確定cat 重定向的過程中，proc檔案系統被删除的檔案無寫入

關于監控，線上應當添加對相關data目錄的 proc deleted句柄的相關監控

如果轉載，請注明博文來源： www.cnblogs.com/xinysu/ ，版權歸 部落格園 蘇家小蘿蔔 所有。望各位支援！

mysql檔案被删 mysql初始化 linux删除檔案 故障處理
上一篇: Windows下Go語言的環境搭建
下一篇: MySQL更新-5.6更新到5.7版本&切換GTID模式

繼續閱讀