一條SQL引起的MySQL主從復制報錯1205

阿新 • • 發佈：2018-03-28

MySQL主從復制 Error_code: 1205 鎖表 SQL優化

大家都知道DBA就像是消（背）防（鍋）員（俠），因為前端應用還有開發上線的新版本都會影響到位於最底層的數據庫，前方稍微有些風吹草動，就能反應在數據庫的性能上。但是有的時候SQL不僅能決定數據庫的性能，還能決定數據庫的生死，今天的案例是開發的一條SQL，引起的MySQL數據庫主從復制報錯，vip漂移問題。

今天下午有客戶反饋發消息有點慢，手機收到幾條報警：

nagios報警如下大致意思就是vip發生了漂移

**** Nagios ***** 

Notification Type: PROBLEM 

Service: check_ha_mysqld 
Host: prod-bjuc-mysql1-vip 
Address: 192.168.87.74 
State: CRITICAL 

Date/Time: Wed Mar 28 14:39:27 CST 2018 

Additional Info: 

CRITICAL: HA Failover from 192.168.87.72 to 192.168.87.123,         
192.168.87.123 result:PROCS OK: 1 processes with command name /usr/sbin/mysqld, args  VIP=192.168.87.74, 192.168.87.72:PROCS OK: 1 processes with command name /usr/sbin/mysqld

Slave_SQL線程停止工作
***** Nagios ***** 

Notification Type: PROBLEM 

Service: check_mysql_health_slave-sql-running 
Host: bjuc-mysql1 
Address: 192.168.87.72 
State: CRITICAL 

Date/Time: Wed Mar 28 14:46:06 CST 2018 

Additional Info: 

CRITICAL - Slave sql is not running

登錄數據庫服務器查看主從復制的狀態，發現報錯1205錯

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.87.123
                  Master_User: zhu
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000481
          Read_Master_Log_Pos: 218802975
               Relay_Log_File: mysql-relay-bin.000428
                Relay_Log_Pos: 2428110
        Relay_Master_Log_File: mysql-bin.000481
             Slave_IO_Running: Yes
            Slave_SQL_Running: No
              Replicate_Do_DB: 
          Replicate_Ignore_DB: performance_schema,information_schema,test,mysql
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: %.%
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 1205
                   Last_Error: Error 'Lock wait timeout exceeded; try restarting transaction' on query. 
                               Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)'
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 182088298
              Relay_Log_Space: 39142986
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: NULL
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 1205
               Last_SQL_Error: Error 'Lock wait timeout exceeded; try restarting transaction' on query. 
                               Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)'
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 6
1 row in set (0.00 sec)

查看錯誤日誌有一下報錯信息：

錯誤日誌中給出了報錯原因和解決方法

tail -70 error.log

180328 14:36:05 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:36:21 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:36:38 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:36:56 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:37:15 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:37:35 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:37:56 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:38:17 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:38:38 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:38:59 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:39:20 [ERROR] Slave SQL: Error 'Lock wait timeout exceeded; try restarting transaction' on query. Default database: 'statusnet'. Query: 'UPDATE notice_status_new set valid = 0 WHERE conversation = 384667 AND user_id IN(4337475,4337529,4337471,4337365)', Error_code: 1205
180328 14:39:20 [ERROR] Slave SQL thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable.
180328 14:39:20 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205
180328 14:39:20 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000481' position 182088298

查看參數結合著兩個參數可以知道主從復制報錯的原因為：

180328 14:39:20 [ERROR] Slave SQL thread retried transaction 10 time(s) in vain, giving up. Consider raising the value of the slave_transaction_retries variable.

180328 14:39:20 [Warning] Slave: Lock wait timeout exceeded; try restarting transaction Error_code: 1205

180328 14:39:20 [ERROR] Error running query, slave SQL thread aborted，Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.000481' position 182088298

因為表notice_status_new產生了鎖，阻塞了這條update語句

參數innodb_lock_wait_time 設置的為15秒，單個事務在等待15秒後開始報1025錯：因為鎖執行超時並重啟事務

參數slave_transaction_retries 設置的為10次，如果事務重試次數超過10次，復制中斷。（但是錯誤日誌中嘗試了11次）

mysql> show variables like '%innodb_lock_wait_timeout%';

+--------------------------+-------+
| Variable_name            | Value |
+--------------------------+-------+
| innodb_lock_wait_timeout | 15    |
+--------------------------+-------+
1 row in set (0.01 sec)

mysql> show variables like '%slave_transaction_retries%';
+---------------------------+-------+
| Variable_name             | Value |
+---------------------------+-------+
| slave_transaction_retries | 10    |
+---------------------------+-------+
1 row in set (0.00 sec)

解決方法：重啟slave後主從復制恢復，並開始追日誌

mysql> stop slave;
Query OK, 0 rows affected (0.02 sec)

mysql> start slave;
Query OK, 0 rows affected (0.00 sec)

mysql> show slave status\G
*************************** 1. row ***************************
               Slave_IO_State: Waiting for master to send event
                  Master_Host: 192.168.87.123
                  Master_User: zhu
                  Master_Port: 3306
                Connect_Retry: 60
              Master_Log_File: mysql-bin.000481
          Read_Master_Log_Pos: 451125456
               Relay_Log_File: mysql-relay-bin.000428
                Relay_Log_Pos: 9541548
        Relay_Master_Log_File: mysql-bin.000481
             Slave_IO_Running: Yes
            Slave_SQL_Running: Yes
              Replicate_Do_DB: 
          Replicate_Ignore_DB: performance_schema,information_schema,test,mysql
           Replicate_Do_Table: 
       Replicate_Ignore_Table: 
      Replicate_Wild_Do_Table: %.%
  Replicate_Wild_Ignore_Table: 
                   Last_Errno: 0
                   Last_Error: 
                 Skip_Counter: 0
          Exec_Master_Log_Pos: 189201736
              Relay_Log_Space: 271465769
              Until_Condition: None
               Until_Log_File: 
                Until_Log_Pos: 0
           Master_SSL_Allowed: No
           Master_SSL_CA_File: 
           Master_SSL_CA_Path: 
              Master_SSL_Cert: 
            Master_SSL_Cipher: 
               Master_SSL_Key: 
        Seconds_Behind_Master: 5184
Master_SSL_Verify_Server_Cert: No
                Last_IO_Errno: 0
                Last_IO_Error: 
               Last_SQL_Errno: 0
               Last_SQL_Error: 
  Replicate_Ignore_Server_Ids: 
             Master_Server_Id: 6
1 row in set (0.00 sec)

vip的問題等到晚上在切回來，線上架構為MM+heartbeat

---------------------------------我是分割線--------------------------

這次問題雖然解決了，但是發現問題我們一定要找到根音，這樣問題才能算是閉環。

為什麽會產生這個鎖呢，因為記錄鎖信息的表都是實時的，現在查不出當時的鎖信息，但是從存儲引擎的運行狀態中還是能發現一些問題，數據庫出現了死鎖！！顯然在update這張表一定會等待的！！

發現了一條奇葩SQL，被鎖的那張表也是notice_status_new

UPDATE notice_status_new SET count = count + 1, push_count = push_count + 1 WHERE conversation = 2609759 AND user_id != 7384662 AND user_id IN(7359498)

show engine innodb status\G 
截取死鎖的這部分
------------------------
LATEST DETECTED DEADLOCK
------------------------
180328 14:33:52
*** (1) TRANSACTION:
TRANSACTION 1B285E9F9, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 3972036, OS thread handle 0x7fc0c3464700, query id 2525495433 192.168.87.42 dstatusnet Updating
UPDATE notice_status_new SET count = count + 1, push_count = push_count + 1 WHERE conversation = 2609759 AND user_id != 7384662 AND user_id IN(7359498)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3535 page no 65360 n bits 448 index `conv_user` of table `statusnet`.`notice_status_new` trx id 1B285E9F9 lock_mode X locks rec but not gap waiting
Record lock, heap no 241 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 000000000027d25f; asc      ' _;;
 1: len 4; hex 80704c0a; asc  pL ;;
 2: len 4; hex 80b1a0fe; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 1B285E9FD, ACTIVE 0 sec starting index read, thread declared inside InnoDB 500
mysql tables in use 1, locked 1
4 lock struct(s), heap size 1248, 3 row lock(s), undo log entries 1
MySQL thread id 3867908, OS thread handle 0x7fbfc6d4f700, query id 2525495437 192.168.87.42 dstatusnet Updating
UPDATE notice_status_new SET count = count + 1, push_count = push_count + 1 WHERE conversation = 2609759 AND user_id != 7359498 AND user_id IN(7384662)
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 3535 page no 65360 n bits 448 index `conv_user` of table `statusnet`.`notice_status_new` trx id 1B285E9FD lock_mode X locks rec but not gap
Record lock, heap no 241 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 000000000027d25f; asc      ' _;;
 1: len 4; hex 80704c0a; asc  pL ;;
 2: len 4; hex 80b1a0fe; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 3535 page no 65360 n bits 448 index `conv_user` of table `statusnet`.`notice_status_new` trx id 1B285E9FD lock_mode X locks rec but not gap waiting
Record lock, heap no 242 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
 0: len 8; hex 000000000027d25f; asc      ' _;;
 1: len 4; hex 8070ae56; asc  p V;;
 2: len 4; hex 80b1a0fc; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

問題找到了，找對該業務的開發，溝通後決定在周六上線新版本，徹底解決問題。

可以寫一個實時監控鎖的腳本，把內容輸出打印，這樣方便以後定位問題！

一條SQL引起的MySQL主從復制報錯1205

MySQL主從復制 Error_code: 1205 鎖表 SQL優化大家都知道DBA就像是消（背）防（鍋）員（俠），因為前端應用還有開發上線的新版本都會影響到位於最底層的數據庫，前方稍微有些風吹草動，就能反應在數據庫的性能上。但是有的時候SQL不僅能決定數據庫的性能，還能決定數據庫的生死，

一條SQL引起的MySQL主從復制報錯1205

一條SQL引起的MySQL主從復制報錯1205

MySQL主從復制（一）

mysql主從復制（一主一從）

mysql主從復制

MySQL主從復制原理深入解析與練習

mysql 主從復制配置

MySQL 主從復制擴展

Mysql 主從復制及一些要註意的特殊設置

2-16 mysql主從復制

mysql主從復制讀寫分離

Ansible 管理MySQL主從復制

mysql主從復制配置

MySQL主從復制Galera

MySQL主從復制與讀寫分離

mysql主從復制實戰——詳細

zabbix監控mysql主從復制

MySQL主從復制的實現過程

MySQL主從復制技術與讀寫分離技術amoeba應用

Linux下MySQL主從復制（二）

mysql 主從復制原理

一條SQL引起的MySQL主從復制報錯1205

相關推薦