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

時間  2019-12-14
標籤 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

    備份錯誤日誌以下：html

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).node

    說明xtrabckup 同步 redo log 到完成的時候，自身的 redo log 最後的 lsn 跟 當前數據庫的 ib_logfile文件最後的 lsn對比，發現不匹配。mysql

    先檢查備份失敗實例內的 ib_logfile 文件：linux

  
    正常 ib_logfile 文件的change time 應該是跟數據庫的初始化時間一致，由於沒有修改 文件的權限，可是顯示的change time 明顯晚與實例的運行時間，懷疑是否這幾個ib_logfile[*] 文件被覆蓋！
    爲驗證ib_logfile[*] 文件被覆蓋，檢查 mysql 進程下是否有 deleted 句柄，截圖以下，發現 ib_logfile[*]文件確實被覆蓋。

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個文件後檢查
 

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 是寫入到 被刪除的文件的。

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. 檢查從庫追上主庫
        5. 主從切換
        6. 舊主新從，中止複製，重定向文件內容 或者重作 從庫
  2. 如果從庫文件被刪
    1. 方案1
      1. 從庫中止複製
      2. 從庫上，根據deleted句柄重定向被刪除的數據塊到原先的磁盤位置，例： cat /proc/16979/fd/36 > /apps/dbdat/mysql5_data3306/sophia/tba.ibd
    2. 方案2
      1. 重作 舊主庫，重作後恢復從庫使用

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安裝的時候，讀取配置文件的優先順序： 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
Global options
$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個數據庫目錄及表格文件，同時生成 ibdata一、ib_logfile[*]等文件，是否能夠判斷，初始化過程當中，須要指定跟 ibdata一、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擔憂該配置文件被惡意修改，故會忽略該文件，不讀該文件配置
        2. mysqld: [Warning] World-writable config file '/etc/my.cnf' is ignored.
        3. 注意查看 配置文件權限 不是 777 權限

6 思考與改進

關於部署，使用defaults-file指定部署sql

關於恢復，注意主從處理及readonly 處理，確保cat 重定向的過程當中，proc文件系統被刪除的文件無寫入數據庫

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

相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程