MySQLのバイナリログを見てスレーブ停止の原因を調査する

以前スレーブ側の更新がとまっていることに気付きました :x001:
その時のトラブルシューティングの手順です。

１．スレーブ側で、SlaveS tatusを確認する

まずはスレーブの状態を確認し、何が停止しているかをチェックしました。

mysql> show slave status\G
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 192.168.xxx.xxx
                Master_User: xxx
                Master_Port: xxx
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000009         ←①スレーブのI/Oスレッドが現在処理中のマスタのバイナリログファイル名。
        Read_Master_Log_Pos: 242153177                ←①スレーブのI/Oスレッドが読み込んだマスタのバイナリログの位置。
             Relay_Log_File: mysqld-relay-bin.002512  ←②スレーブのSQLスレッドが現在処理中のスレーブのリレーログファイル名。(※重要)
              Relay_Log_Pos: 18199795                 ←②スレーブのSQLスレッドが実行完了したスレーブのリレーログの位置(※重要)
      Relay_Master_Log_File: mysql-bin.000009         ←③スレーブのSQLスレッドが最後に実行したクエリが記録されていたマスタのバイナリログファイル名。
           Slave_IO_Running: Yes
          Slave_SQL_Running: No ★
            Replicate_Do_DB:
        Replicate_Ignore_DB:
         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: 221243106                ←③スレーブのSQLスレッドが最後に実行したクエリの、マスタのバイナリログでの位置。
            Relay_Log_Space: 39111006
            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
1 row in set (0.00 sec)

①～③は対応している項目を同じ番号にしただけす
『Slave_SQL_Running: No』なので、SQLスレッドが停止していることがわかります。
スレーブへのSQLのインサートエラーのようです。
何故か『Last_Errno: 0』なので原因はよくわかりません。

mysql> stop slave
mysql> start slave

をしてみましたが、やはりSQLスレッドは実行されませんでした。

この後バイナリログを確認するためにはリレーログファイル名とリレーログファイルの位置は重要です。
ここで押さえておきましょう。

２．スレーブ側のログを確認してみる

#cat /var/log/ mysqld.log
120803 10:19:24 [Note] Slave I/O thread: connected to master 'xxx@192.168.xxx.xxx:3306',  replication started in log 'mysql-bin.000009' at position 237373898
120803 10:24:50 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000009' at position 221243106, relay log '/var/run/mysqld/mysqld-relay-bin.002512' position: 18199795
120803 10:24:50 [Note] Slave SQL thread exiting, replication stopped in log 'mysql-bin.000009' at position 221243106
120803 12:02:31 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.000009' at position 221243106, relay log '/var/run/mysqld/mysqld-relay-bin.002512' position: 18199795

確かにSQLスレッドが停止しているのは確認できたが、やはり原因は不明です。
ちなみにここで表示されている’mysql-bin.000009′ at position 221243106はマスタにあるバイナリログの位置です。

３．スレーブ側でバイナリログのパスを確認する

これは覚えていらっしゃる方は不要ですよね・・・ :x001:
ファイル名は１のshow slave statusで確認できますが、
実際のファイルのパスはこれで確認できます。

#cat /var/lib/mysql/relay-log.info
/var/run/mysqld/mysqld-relay-bin.002516　←★バイナリログのパスを確認できる
4985047
mysql-bin.000009
242358710

４．スレーブ側でmysqlbinlogコマンドを使ってバイナリログを確認する

スレーブは、マスターから受信したバイナリログをそのまま実行しているだけです。
バイナリログのどこでエラーが発生したかを確認すると、
どういったコマンド・SQLを発行したときに停止したかを確認できます。
重要なことは、どのバイナリログファイルなのか、どの位置(ポジション)なのかを事前に確認することです。

# mysqlbinlog -u xxx -p /var/run/mysqld/mysqld-relay-bin.002512 --start-position=18199874
Enter password:
/*!40019 SET @@session.max_insert_delayed_threads=0*/;
/*!50003 SET @OLD_COMPLETION_TYPE=@@COMPLETION_TYPE,COMPLETION_TYPE=0*/;
DELIMITER /*!*/;
# at 18199874 ←★atがバイナリログの位置(position)を表している
#120802  3:47:18 server id xxx  end_log_pos 28  Intvar
SET INSERT_ID=55738/*!*/;
# at 18199902
#120802  3:47:18 server id xxx  end_log_pos 1762        Query   thread_id=93510297      exec_time=0     error_code=0
use <DB名>/*!*/; ←★DBの選択
SET TIMESTAMP=1343846838/*!*/;
SET @@session.foreign_key_checks=1, @@session.sql_auto_is_null=1, @@session.unique_checks=1/*!*/;
SET @@session.sql_mode=2097152/*!*/;
/*!\C latin1 *//*!*/;
SET @@session.character_set_client=8,@@session.collation_connection=8,@@session.collation_server=8/*!*/;
SET @@session.time_zone='SYSTEM'/*!*/;
insert into <SQL文>/*!*/; ←★INSERTが走っている・・・
# at 18201636
#120802  3:47:19 server id xxx  end_log_pos 1790        Intvar
SET INSERT_ID=55588/*!*/;
# at 18201664
#120802  3:47:19 server id xxx  end_log_pos 2738        Query   thread_id=93510297      exec_time=0     error_code=0
SET TIMESTAMP=1343846839/*!*/;
insert into <SQL文> ←★INSERTが走っている・・・

positionで指定するのは、バイナリログのatにある値です。

５．原因を究明する

今回の場合、インサートの後に停止しているようです。
スレーブ側のDBを見るとすでに同じキーの値がありました・・・ :x001:
スレーブ側の該当データを削除して、stop slave, start slaveコマンドを実行すると無事スレーブSQLスレッドも動き出しました。

本来ならばレプリケーション側のmy.cnfにはread_onlyを設定しておくべきでしょう。
スレーブ側での更新系クエリを禁止することで今回のような障害は防ぐことができます。
しかし、私のように十分なハード環境もない場合には、レプリケーション側をテストで利用する必用も多々あります。
しかたありません。

バイナリログを確認する手順のまとめ

結局不要な手順が多かったのでまとめておきます。