s這是學習筆記的第?2031?篇文章

? 最近有個業務的MySQL復制問題還是比較多，做了事務降維之后，把一些敏感操作和線上環境隔離起來，整體的效果好了許多，不過今天在外面的時候，又收到一條報警短信，讓我心里咯噔一下。?

? 這個環境是一個中間件的分布式環境，有8個物理節點(主庫)，即有6個主庫+8個從庫，我查看了下郵件，發現報錯的這個環境是昨天同事幫忙新建的從庫，到今天才這么短的時間，而且是基于GTID復制的模式，又出現了這類問題，我的心里還是比較忐忑的，因為如果我再收到幾條其他環境類似的復制錯誤，那么毫無疑問就屬于一起計劃外的故障了。

? ?故障離我們很近，但是在不同的時間有不同的理解。因為這段時間的做了數據遷移的一些高可用測試，壓力測試，數據重構，整體該做的工作都做差不多了，到了臨門一腳的時候，出現一些頻繁的問題，我讓我有所措手不及，而問題能夠定位可控，很容易理解，可以查漏補缺，而如果問題是集中出現，那就說明之前的工作沒有做到位，一旦發現嚴重的bug導致服務不可用，如果反復出現，不管過程如何，結果就是不合格的。這種感覺就好比是高速公路給汽車換輪胎，時間緊，任務重。

??所幸的是，我等了一會沒有再收到其他環境的問題，所以一個基本的定位：不是很嚴重。?

? 等我回到酒店之后，開始處理的時候，腦海里一直在琢磨，到底是一條什么樣的SQL語句會導致這樣奇怪的問題。

??很快就查到了相關的描述信息：

? ?LAST_ERROR_MESSAGE: Worker 0 failed executing transaction 'db8f9860-8202-11e9-991e-005056b7f69e:854286845' at master log mysqlbin.000601, end_log_pos 936077509; Could not execute Update_rows event on table dbo_testdb.dbo_testdata; Can't find record in 'dbo_testdata', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysqlbin.000601, end_log_pos 936077509

看起來問題是在binlog日志000601的偏移量936077509附近，看到這個偏移量心里一糾，可以看到文件已經超過900M了，解析起來已經有一些性能問題了。?

查看show slave status的結果：

?????????????Slave_IO_Running: Yes

? ? ? ? ? ? Slave_SQL_Running: No

可以看到IO_thread依然可用，說明復制的過程中整體的數據傳輸是OK的，是在應用的時候出現了問題 。?

我使用如下的語句開始解析這個偏移量附近的一些錯誤。?

/usr/local/mysql/bin/mysqlbinlog --no-defaults -v -v --base64-output=DECODE-ROWS mysqlbin.000601 | grep -A '10' 936077509

得到了如下的結果：

#190705 19:27:15 server id 211? end_log_pos 936077509 CRC32 0x590574c3? Update_rows: table id 599753 flags: STMT_END_F

### UPDATE `dbo_testdb`.`dbo_testdata`

### WHERE

###? ?@1=748890203 /* LONGINT meta=0 nullable=0 is_null=0 */

###? ?@2=60 /* INT meta=0 nullable=0 is_null=0 */

###? ?@3=13 /* INT meta=0 nullable=0 is_null=0 */

###? ?@4='2019-07-05 19:27:15' /* DATETIME(0) meta=0 nullable=0 is_null=0 */

###? ?@5='2019-07-05 19:27:15' /* DATETIME(0) meta=0 nullable=0 is_null=0 */

###? ?@6=0 /* LONGINT meta=0 nullable=0 is_null=0 */

### SET

###? ?@1=748890203 /* LONGINT meta=0 nullable=0 is_null=0 */

--

# at 936077509

#190705 19:27:15 server id 211? end_log_pos 936077540 CRC32 0x78404313? Xid = 221915192

COMMIT/*!*/;

# at 936077540

#190705 19:27:15 server id 211? end_log_pos 936077605 CRC32 0x6e307159? GTID? ? last_committed=1762227? sequence_number=1762248

SET @@SESSION.GTID_NEXT= 'db8f9860-8202-11e9-991e-005056b7f69e:854286846'/*!*/;

# at 936077605

#190705 19:27:15 server id 211? end_log_pos 936077696 CRC32 0x00c8479d? Query? ?thread_id=854? ?exec_time=0? ? ?error_code=0

SET TIMESTAMP=1562326035/*!*/;

BEGIN

可以看到這是一條update語句，它的格式比較奇怪，如下：

update xxx

where userid=xxxx,value=xxxx

set userid=xxxx

從語句來看明顯是不符合業務場景的，自己變更自己，明顯不合理的。

我們來進一步驗證。

主庫端查看數據，把上面的update轉義成select語句：

select * from `dbo_testdb`.`dbo_testdata`

WHERE

userid=748890203 and?

xxx=60 and

value=13 and

moddate='2019-07-05 19:27:15' and

crtdate='2019-07-05 19:27:15' and

modver=0?

發現主庫端和從庫端都不存在這條語句。?

所以這就牽扯出來兩個問題：

1)如果MySQL在主庫端的SQL語句沒有發生數據變更，是否會依然產生binlog

2)一條update語句，在MySQL里的解析應該是類似如下的形式：

update xxxx set xxxxx ?where 的形式，在這里明顯沒有走這種解析的方式。?

3)這條語句如何修復，因為后面的數據都等著這個斷點。

4)如果后續還有這種問題，該如何預防。?

我們為了快速修復，經過評估，主從庫端都沒有相應的數據，說明這條語句是沒有產生影響的，我們可以跳過這個事務。?

stop slave;

SET @@SESSION.GTID_NEXT= 'db8f9860-8202-11e9-991e-005056b7f69e:854286846';

begin;commit;

SET SESSION GTID_NEXT = AUTOMATIC;

start slave;

再次嘗試這個問題暫時正常了，在反復驗證中暫時沒有發現問題。?

而后續的進一步驗證得找下環境，會后續繼續說明。

對于問題本身，也需要和研發團隊做一下確認，這種操作的需求需要引導，后續不要再出現。