碼上快樂

相關內容    簡體    繁體

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

本文轉載自   查看原文   2018-09-20 09:48   2438    故障處理/ mysql文件被刪/ MySQL/ linux刪除文件/ 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 文件：

  
    正常 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個數據庫目錄及表格文件，同時生成 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擔心該配置文件被惡意修改，故會忽略該文件，不讀該文件配置
        2. mysqld: [Warning] World-writable config file '/etc/my.cnf' is ignored.
        3. 注意查看 配置文件權限 不是 777 權限

6 思考與改進

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

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

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



 
 
 


免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 記一次.Net Core程序啟動失敗的排查過程 記一次慢sql問題排查過程 記一次OOM問題排查過程 記一次Xmrig挖礦木馬排查過程 記一次線上內存泄漏問題的排查過程 記一次Xmrig挖礦木馬排查過程 記一次線上崩潰問題的排查過程 一次kibana服務失敗的排查過程 記錄一次Mysql死鎖排查過程 記錄一次Mysql死鎖排查過程
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM