利用xtrabackup和binlog增量恢復時提示表記錄不存在案例
一.基本資訊
版本：10.0.20-MariaDB-log
資料檔案和redo log位置:/apps/dbdat/mariadb10_data3306/
bing log位置：/apps/dbdat/mariadb10_data3306/log
主機資訊:mvxl0784 10.16.24.109
配置檔案：/apps/dbdat/mariadb10_data3306/my3306.cnf
二.問題背景及描述
利用xtrabackup工具在2016-05-17 01:11:55時間點的全備加上binlog增量恢復mysql到2016年5月18日0點。
我們檢視備份集中的xtrabackup_info和xtrabackup_binlog_info檔案
cat xtrabackup_info
start_time = 2016-05-17 01:00:01
end_time = 2016-05-17 01:11:55
lock_time = 2
binlog_pos = filename 'mysql-bin.000271', position 291755824, GTID of the last change '0-19873306-348307239'
cat xtrabackup_binlog_info
mysql-bin.000271 291755824 0-19873306-348307239
從上面看到，備份開始時間為2016-05-17 01:00:01，完成時間為2016-05-17 01:11:55，對應的的binlog為mysql-bin.000271，position為291755824。
正常執行完xtrabckup的全備恢復後，對以下binlog檔案進行增量恢復，binlog檔案如下：
[[email protected] backup]$ ls -ltr
total 3751088
-rw-r----- 1 apps apps 536871119 May 18 09:37 mysql-bin.000271
-rw-r----- 1 apps apps 536871210 May 18 09:37 mysql-bin.000272
drwxr-xr-x 8 apps apps 4096 May 18 10:03 xtrabackup_20160517010001
先執行了第一個binlog增量恢復是沒問題：
[[email protected] backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-datetime='2016-05-17 01:11:55'|/apps/svr/mariadb10/bin/mysql -u root -
psafe2016 --socket=/tmp/mysql3306.sock
real 1m13.570s
user 0m19.412s
sys 0m10.718s
接著對第二個binlog檔案再執行時報錯，顯示找不到表t_task_log的記錄:
[
psafe2016 --socket=/tmp/mysql3306.sock
ERROR 1032 (HY000) at line 165805: Can't find record in 't_task_log'
三.問題分析
針對上面報錯，顯示在binlog日誌解析的165805行，我們看下165805行及附件日誌是什麼操作：
165783 # at 1746660
165784 #160517 9:29:50 server id 19873306 end_log_pos 1746698 GTID 0-19873306-348602810
165785 /*!100001 SET @@session.gtid_seq_no=348602810*//*!*/;
165786 BEGIN
165787 /*!*/;
165788 # at 1746698
165789 # at 1746764
165790 #160517 9:29:50 server id 19873306 end_log_pos 1746764 Table_map: `lots`.`t_tracking_log` mapped to number 227
165791 #160517 9:29:50 server id 19873306 end_log_pos 1746839 Write_rows: table id 227 flags: STMT_END_F
165792 ### INSERT INTO `lots`.`t_tracking_log`
165793 ### SET
165794 ### @1=31757386 /* INT meta=0 nullable=0 is_null=0 */
165795 ### @2=NULL /* INT meta=0 nullable=1 is_null=1 */
165796 ### @3='AD16051501234897' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
165797 ### @4='2016-05-17 09:29:51.245' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
165798 ### @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
165799 ### @6=NULL /* VARSTRING(150) meta=6000 nullable=1 is_null=1 */
165800 # at 1746839
165801 #160517 9:29:50 server id 19873306 end_log_pos 1746866 Xid = 78680652
165802 COMMIT/*!*/;
165803 # at 1746866
165804 #160517 9:29:50 server id 19873306 end_log_pos 1746904 GTID 0-19873306-348602811
165805 /*!100001 SET @@session.gtid_seq_no=348602811*//*!*/;
165806 BEGIN
165807 /*!*/;
165808 # at 1746904
165809 # at 1746996
165810 #160517 9:29:50 server id 19873306 end_log_pos 1746996 Table_map: `lots`.`t_carrier_tracking` mapped to number 226
165811 #160517 9:29:50 server id 19873306 end_log_pos 1747217 Write_rows: table id 226 flags: STMT_END_F
165812 ### INSERT INTO `lots`.`t_carrier_tracking`
165813 ### SET
............................................
...............................................
上面165805行及附近日誌都沒有與表t_task_log相關的操作，怪事真多啊。
檢視錯誤日誌的最後部分顯示如下：
Version: '10.0.20-MariaDB-log' socket: '/tmp/mysql3306.sock' port: 3306 MariaDB Server
160518 16:21:57 [ERROR] Slave SQL: Could not execute Update_rows_v1 event on table lots.t_task_log; Can't find record in 't_task_log
', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log FIRST, end_log_pos 2459743, Internal MariaDB error c
ode: 1032
原來找不到表記錄發生的位置是在binlog中的2459743。然後再通過分析binlog，找到2459743位置所發生的事務操作如下：
# at 2459207
#160517 9:30:00 server id 19873306 end_log_pos 2459245 GTID 0-19873306-348605082
/*!100001 SET @@session.gtid_seq_no=348605082*//*!*/;
BEGIN
/*!*/;
# at 2459245
# at 2459311
#160517 9:30:00 server id 19873306 end_log_pos 2459311 Table_map: `lots`.`t_task_log` mapped to number 233
#160517 9:30:00 server id 19873306 end_log_pos 2459743 Update_rows: table id 233 flags: STMT_END_F
### UPDATE `lots`.`t_task_log`
### WHERE
### @1=369680 /* INT meta=0 nullable=0 is_null=0 */
### @2=21 /* INT meta=0 nullable=1 is_null=0 */
### @3='HTKYQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
### @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
### @7=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
### @8=NULL /* DATETIME meta=15000 nullable=1 is_null=1 */
### @9=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
### SET
### @1=369680 /* INT meta=0 nullable=0 is_null=0 */
### @2=21 /* INT meta=0 nullable=1 is_null=0 */
### @3='HTKYQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @5='success' /* VARSTRING(30) meta=30 nullable=1 is_null=0 */
### @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
### @7=300821 /* INT meta=0 nullable=1 is_null=0 */
### @8='任務ID：21，名稱：HTKYQueryCarrierTrackingJob，任務觸發器：Express.HTKYQueryCarrierTrackingJob，任務開始執行......任務執行
成功！，執行耗時：300821ms，開始時間：2016-05-17 09:25:00，結束時間：2016-05-17 09:30:01' /* VARSTRING(15000) meta=15000 nullable=1
is_null=0 */
### @9=2016-05-17 09:30:01 /* DATETIME meta=0 nullable=1 is_null=0 */
# at 2459743
#160517 9:30:00 server id 19873306 end_log_pos 2459770 Xid = 78694692
COMMIT/*!*/;
# at 2459770
查看錶t_task_log的定義：
show create table t_task_log\G
*************************** 1. row ***************************
Table: t_task_log
Create Table: CREATE TABLE `t_task_log` (
`id` int(11) NOT NULL AUTO_INCREMENT,
`job_id` int(11) DEFAULT NULL COMMENT '任務ID',
`job_name` varchar(50) DEFAULT NULL COMMENT '任務名稱',
`cron_expression` varchar(50) DEFAULT NULL COMMENT 'cron表示式',
`execution_status` varchar(10) DEFAULT NULL COMMENT '執行狀態 success|error',
`execution_date` datetime DEFAULT NULL COMMENT '執行時間',
`execution_time` int(11) DEFAULT NULL COMMENT '執行耗時',
`description` varchar(5000) DEFAULT NULL COMMENT '描述',
`end_date` datetime DEFAULT NULL COMMENT '結束時間',
PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=369694 DEFAULT CHARSET=utf8 COMMENT='JOB任務執行記錄日誌'
1 row in set (0.02 sec)
查詢execution_date欄位值為2016-05-17 09:25:00的記錄，是否存在，下面返回為空，確認表記錄不存在的原因是因為第一個binlog恢復應用到庫中時執行有異常。
(product)[email protected] [lots]> select execution_status,execution_time,end_date from `lots`.`t_task_log` where execution_date='2016-05-17 09:25:00';
Empty set (4.83 sec)
在對第一個binlog恢復時，沒有看到報錯，如是重新再來恢復一次，這次將--start-datetime引數改為--start-position，並開啟genaral_log。
time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-position=291755824|/apps/svr/mariadb10/bin/mysql -u root -psafe2016 --socket=/tmp/mysql3306.sock
ERROR 2006 (HY000) at line 3634523: MySQL server has gone away
real 1m14.251s
user 0m18.285s
sys 0m10.723s
先看錯誤日誌，錯誤日誌顯示沒有報錯：
160519 9:51:31 [Note] InnoDB: Using mutexes to ref count buffer pool pages
160519 9:51:31 [Note] InnoDB: The InnoDB memory heap is disabled
160519 9:51:31 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
160519 9:51:31 [Note] InnoDB: Memory barrier is not used
160519 9:51:31 [Note] InnoDB: Compressed tables use zlib 1.2.3
160519 9:51:31 [Note] InnoDB: Using Linux native AIO
160519 9:51:31 [Note] InnoDB: Using CPU crc32 instructions
160519 9:51:31 [Note] InnoDB: Initializing buffer pool, size = 21.0G
160519 9:51:32 [Note] InnoDB: Completed initialization of buffer pool
160519 9:51:32 [Note] InnoDB: Highest supported file format is Barracuda.
160519 9:51:34 [Note] InnoDB: 128 rollback segment(s) are active.
160519 9:51:34 [Note] InnoDB: Waiting for purge to start
160519 9:51:34 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.24-72.2 started; log sequence number 377271951224
160519 9:51:34 [Note] Plugin 'FEEDBACK' is disabled.
160519 9:51:34 [Note] Server socket created on IP: '0.0.0.0'.
160519 9:51:34 [Note] Event Scheduler: Loaded 0 events
160519 9:51:34 [Note] Event Scheduler: scheduler thread started with id 2
160519 9:51:34 [Note] /apps/svr/mariadb10/bin/mysqld: ready for connections.
Version: '10.0.20-MariaDB-log' socket: '/tmp/mysql3306.sock' port: 3307 MariaDB Server
看一般日誌最後顯示幾行：
160519 10:02:48 6 Query /*!100001 SET @@session.gtid_seq_no=348475348*/
6 Query BEGIN
一般日誌顯示，在準備執行gtid為348475348的事務時，與mysql沒有互動資訊了，說明從lsn 348475348 開始binlog就沒有執行恢復應用到庫中。
我們通過execution_date欄位值為2016-05-17 09:25:00的記錄，查詢這條記錄是在binlog中什麼位置插入的，如下顯示是lsn 348528548這條事務。
# at 515432241
#160517 9:24:59 server id 19873306 end_log_pos 515432279 GTID 0-19873306-348528548
/*!100001 SET @@session.gtid_seq_no=348528548*//*!*/;
BEGIN
/*!*/;
# at 515432279
# at 515432345
#160517 9:24:59 server id 19873306 end_log_pos 515432345 Table_map: `lots`.`t_task_log` mapped to number 233
#160517 9:24:59 server id 19873306 end_log_pos 515432435 Write_rows: table id 233 flags: STMT_END_F
### INSERT INTO `lots`.`t_task_log`
### SET
### @1=369677 /* INT meta=0 nullable=0 is_null=0 */
### @2=25 /* INT meta=0 nullable=1 is_null=0 */
### @3='TTKQueryCarrierTrackingJob' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @4='0 5/10 * * * ?' /* VARSTRING(150) meta=150 nullable=1 is_null=0 */
### @5=NULL /* VARSTRING(150) meta=30 nullable=1 is_null=1 */
### @6=2016-05-17 09:25:00 /* DATETIME meta=0 nullable=1 is_null=0 */
### @7=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
### @8=NULL /* DATETIME meta=15000 nullable=1 is_null=1 */
### @9=NULL /* DATETIME meta=0 nullable=1 is_null=1 */
# at 515432435
#160517 9:24:59 server id 19873306 end_log_pos 515432462 Xid = 78203609
COMMIT/*!*/;
# at 515432462
上面的原因搞清了，回到原來報錯：ERROR 2006 (HY000)，從網上查詢顯示，批量資料操作和執行時該報錯與下面引數設定有關，我們檢查一下以下三個引數大小：
max_allowed_packet=64m
interactive_timeout=120
wait_timeout=120
四.問題解決
把上面值分別調整為：
max_allowed_packet=200m
interactive_timeout=600
wait_timeout=600
重新再做一次前面步驟(當然接著報錯位置開始增量恢復也行):
[[email protected] backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-position=291755824|/apps/svr/mariadb10/bin/mysql -u root -psafe2016 --
socket=/tmp/mysql3306.sock
real 3m15.437s
user 0m28.510s
sys 0m18.515s
[[email protected] backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000272 --stop-datetime='2016-05-18 00:00:00'|/apps/svr/mariadb10/bin/mysql -u root -
psafe2016 --socket=/tmp/mysql3306.sock
real 7m2.584s
user 1m40.549s
sys 1m8.097s
檢視上面找不到表記錄的位置的SQL執行情況，可以正常返回值，說明有成功恢復。
(product)[email protected] [(none)]> select execution_status,execution_time,end_date from `lots`.`t_task_log` where execution_date='2016-05-17 09:25:00';
+------------------+----------------+---------------------+
| execution_status | execution_time | end_date |
+------------------+----------------+---------------------+
| success | 218239 | 2016-05-17 09:28:38 |
| success | 859612 | 2016-05-17 09:39:19 |
| success | 519037 | 2016-05-17 09:33:39 |
| success | 9845 | 2016-05-17 09:25:10 |
| success | 528138 | 2016-05-17 09:33:48 |
| success | 300821 | 2016-05-17 09:30:01 |
| success | 528493 | 2016-05-17 09:33:48 |
+------------------+----------------+---------------------+
7 rows in set (6.50 sec)
問題到此已解決了。
五.--start-datetime不報錯，而--start-position有報錯？
針對這個問題，後面我又重新做了一次恢復，實際上同樣也會報錯，估計是當時沒有看清楚或copy資訊時漏掉了，自己坑自己了，折騰好幾次。
[[email protected] backup]$ time /apps/svr/mariadb10/bin/mysqlbinlog mysql-bin.000271 --start-datetime='2016-05-17 01:11:55'|/apps/svr/mariadb10/bin/mysql -u root -
psafe2016 --socket=/tmp/mysql3306.sock
ERROR 2006 (HY000) at line 3634523: MySQL server has gone away
real 1m6.817s
user 0m18.507s
sys 0m9.851s
不要放過任何命令返回資訊，特別是報錯資訊!
相關推薦
利用xtrabackup和binlog增量恢復時提示表記錄不存在案例
一.基本資訊版本：10.0.20-MariaDB-log 資料檔案和redo log位置:/apps/dbdat/mariadb10_data3306/ bing log位置：/apps/dbdat/mariadb10_data3306/log 主機資訊:mvxl0784
mysql5.6使用xtrabackup和binlog進行完全恢復
1、連輸mysql，檢視mysql版本：[[email protected] binlog]$ mysql -uroot -p Enter password: Welcome to the MySQL monitor. Commands end with ; o
Mysql之binlog日誌說明及利用binlog日誌恢復數據操作記錄
Language 命令 ani art ase 回來 log日誌 slaves update 眾所周知，binlog日誌對於mysql數據庫來說是十分重要的。在數據丟失的緊急情況下，我們往往會想到用binlog日誌功能進行數據恢復（定時全備份+binlog日誌恢復增量數據部
java和groovy混合程式設計時提示找不到符合錯誤解決辦法
本人在使用java和groovy混合程式設計時，發現一個問題，當java和groovy相互呼叫的過程中在本機執行沒有任何問題，但當弄到Jenkins上之後總是報錯，本機使用gradle執行build的task的時候，也是報錯，資訊如下： 錯誤: 找不到符號 import com.fission
處理一個關於binlog增量恢復很慢的問題
今天幫網友處理了一個關於binlog增量恢復很慢的問題。問題描述： 網友是先通過xtrabackup將mysql全量恢復到測試環境中，然後再增量恢復binlog，具體操作為：用mysqlbinlog -v -v --base64-output=DECODE-ROWS
在網頁中打開word和excel文件時提示文件已損壞，無法打開的解決辦法
保護 操作 動力 -o 系統 系統環境 是我 所有 https 系統環境：安裝win10的PC機，辦公軟件安裝有office2013。問題描述：在使用華天動力OA過程中，部分審批表單的附件中有word或excel文件，如果點擊word或excel文件，點擊“打開”，會彈出提
vs2013新建MVC項目時提示系統找不到指定文件（異常來自HRESULT：0x80070002）
描述 studio ack 對話框 asp.net vs2013 提示 系統找不到指定文件 uget 一．問題描述 1.打開vs2013，選擇”文件|新建|項目”,彈出如下對話框。 2.點擊左側的“Web”，選擇“ASP.NET Web 應用程序”,點擊確定
#OpenCV##MFC#利用MFC和OpenCV通過系統對話框打開和保存圖片
代碼 pat pda show 選擇 gif buffer length anti 打開圖片： void CImageProDlg::OnImageopen() { // TODO: 在此添加命令處理程序代碼 Invalidate(); CFil
如何解決Visual Studio2010 編譯時提示系統找不到指定檔案問題
1、解決辦法如下： 2、選擇配置屬性-->清單工具-->輸入和輸出-->嵌入清單-->否 這種方式比較麻煩的是，每建立一個工程時都要修改。 方法二（永久解決）（個人親測可行，不代表通用）： 在我的電腦搜尋cvtres.exe
make時提示GCC找不到，但又能查到版本問題
[email protected]:~/linux/tiny6410/linux-2.6.38$ make make: gcc: Command not found HOSTCC scripts/kconfig/conf.o /bin/sh: 1
linux安裝軟體時提示軟體包不存在處理方法
軟體包不存在時可能是被安裝軟體的軟體源沒有安裝，我的是cent os，安裝w3m時，出現這個問題，解決辦法：先安裝軟體源（epel-release），然後更新系統包，最後執行安裝軟體操作，就可以成功了。以安裝w3m為例： 1、安裝w3m的軟體源：epel-release y
Mysql備份（全量+增量+恢復）方案操作記錄
1、開啟mysql的binlog日誌&檢視$備份 2、shell指令碼 mysqldump 變數說明 --all-databases針對所有資料庫進行備份 --databases databasename 針對單個數據庫進行備份 --flush-logs為結束當前
linux ssh 到遠端伺服器執行命令和crontab中執行命令提示命令找不到的問題
使用ssh ip "hadoop" 命令時，提示找不到hadoop命令。 因為hadoop是在/etc/profile配置的，ssh到一臺伺服器上時，會執行使用者環境。 而ssh到一臺伺服器上，帶著命
新增分割槽格式化時提示裝置檔案不存在：--- No such file or directory的處理方法
【原文連結】：http://blog.itpub.net/28874898/viewspace-774249/ 在系統中的空餘空間新增新的分割槽： fdisk /dev/sda (第一塊硬碟上)，進入分割槽命令列後，根據自己的需求一步步往下走，不詳細描述。分好之後
啟動WebLogic時提示：此時不應有\java\jdk1.8.0_144\lib\dt.jar;
起因 公司專案環境需要weblogic ，所以配置完eclipse外掛後需要啟動。 問題 啟動後控制檯報錯紅字如下： 此時不應有\java\jdk1.8.0_144\lib\dt.jar; 解決方案 我的電腦作業系統是64位的，但是jdk版本裝的
ssh用私鑰登入遠端伺服器時提示私鑰不安全問題解決
ssh用私鑰ding_test.pem登陸伺服器11.10.37.54 [email protected]:~# ssh -i ding_test.pem [email pro
SVN客戶端在點選CheckOut時提示系統找不到指定目錄
因為之前安裝的是SVN客戶端的1.7版，後來因為種種原因解除安裝了，裝上了1.6版的，但是出現了一個問題，我之前下載的伺服器上的東西不能更新了，提示我版本過舊，於是我就又卸了，裝上了1.7版的，可是這時又一個問題是我一
解決【關於javascript呼叫ocx控制元件時提示：物件不支援“setUrl”屬性或方法】
因最近工作需要，要開發一款視訊播放的ocx控制元件。但我是第一次開發ocx控制元件，遇到不少問題，走了不少彎路。現將所遇問題做個記錄，方便後來人檢視。問題描述：ocx控制元件中，新增一個名為“setUrl(BSTR url)”的ocx介面方法，以供瀏覽器js程式碼呼叫傳值給o
MySQL插入資料時，如果記錄不存在則insert，如果存在則update
MySQL 當記錄不存在時insert，當記錄存在時更新 網上基本有三種解決方法。 第一種： 示例一：insert多條記錄 假設有一個主鍵為 client_id 的 clients 表，可以使用下面的語句： INSERT INTO clients (clien
使用了資料庫 發現總是崩潰 提示表找不到 或者欄位不存在之類的
import java.io.Serializable; @Table(name = "CommonCityBean") public class CommonCityBean implements Serializable { @Id(column = "tid"