slaveのレプリケーションが止まったら時間操作系のスタンドで直すことができる

MySQLがあって、masterのDBとslaveのDBがあって、masterからslaveにレプリケーションしている。
割となんてことのない光景です。
朝の食卓にパンとコーヒーとミルクが並んでいるくらい、ありふれた光景です。
「朝は和食だろ！」という方は、MySQLではなくEXCELをおススメします（理不尽！

で、slaveのレプリケーションが何らかの理由で止まる。
slaveが読み取り専用等でサービスに使われておらず、単にバックアップのためだけであれば、まだ慌てる時間じゃありません。
実サービスに影響はないので、おちついて対応しましょう。
パンが少しだけ焦げたのかもしれません。

本日の朝食はこんなコースです。
嫌ですね。食あたり起こしますね。

１．現状確認
２．対応
３．原因調査

２と３は逆になることもあります。
原因を特定しないと直せないケースや、原因を解決しないと一時的に対応しても再発するケースなどがそれです。
今回は実サービスに直接影響が出ていないので、とりあえずの一次対応を急いで行い、そのあとでじっくりと調査する、という作戦にしました。

slaveのmysqlに入ります。
そしてslaveのstatusを見るコマンド。

show slave status\G

つまり現状確認ですね。

mysql> show slave status\G
*************************** 1. row ***************************
Slave_IO_State: Waiting for master to send event
Master_Host: 123.45.6.789
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysqld-bin.003755
Read_Master_Log_Pos: 714615665
Relay_Log_File: mysqld-relay-bin.004023
Relay_Log_Pos: 672229502
Relay_Master_Log_File: mysqld-bin.003748
Slave_IO_Running: Yes
Slave_SQL_Running: No
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: resaku_count
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 1053
Last_Error: Query partially completed on the master (error on master: 1053) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: ‘Insert into resaku_param_new
(file_ymd, cookie_id, param_id, param, param_key, param_val, date, start_time, end_time, week_no_year, week_no_month, uu_count,
cnt_m, cnt_2, cnt_3, cnt_4, cnt_5, cnt_7, create_date)
select file_ymd, cookie_id, param_id, param, param_key, param_val, date, start_time, end_time, week_no_year, week_no_month, uu_count,
cnt_m, cnt_2, cnt_3, cnt_4, cnt_5, 0, create_date from resaku_param where file_ymd between ‘20150925’ and ‘20150930”
Skip_Counter: 0
Exec_Master_Log_Pos: 672229355
Relay_Log_Space: 8230816700
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: 1053
Last_SQL_Error: Query partially completed on the master (error on master: 1053) and was aborted. There is a chance that your master is inconsistent at this point. If you are sure that your master is ok, run this query manually on the slave and then restart the slave with SET GLOBAL SQL_SLAVE_SKIP_COUNTER=1; START SLAVE; . Query: ‘Insert into resaku_new
(file_ymd, cookie_id, param_id, param, param_key, param_val, date, start_time, end_time, week_no_year, week_no_month, uu_count,
cnt_m, cnt_2, cnt_3, cnt_4, cnt_5, cnt_7, create_date)
select file_ymd, cookie_id, param_id, param, param_key, param_val, date, start_time, end_time, week_no_year, week_no_month, uu_count,
cnt_m, cnt_2, cnt_3, cnt_4, cnt_5, 0, create_date from resaku_param where file_ymd between ‘20150925’ and ‘20150930”
Replicate_Ignore_Server_Ids:
Master_Server_Id: 499
1 row in set (0.00 sec)

ポイントはこれ。

Slave_IO_Running: Yes

masterのレプリケーションは動いてるよ！

Slave_SQL_Running: No

slaveのレプリケーションは　へんじがないただのしかばねのようだ

Last_Error　は、「このクエリが実行されたらレプリケーションが死んだよ」ということです。

そしてそのログ名と止まったログの位置はこれで確認できます。

Relay_Log_File: mysqld-relay-bin.004023
Relay_Log_Pos: 672229502

できませんでした（早ッ

ググって出てきた方法全部試したのですが、どれも動かなかったりログが流れてしまったりで「こうしたら→こうなる！」的な情報皆無。

まあ場所を特定できたところで、このクエリがある限りレプリケーションはダメであり、かつこのクエリは既に実行されているという事実は変わりません。

覆水盆に返らず。
覆水盆にドント・バイツァ・ダスト。
焦げたパンを悔やむな。
↑今適当に作ったけどこれ結構良くないですか？

まあようするに、このクエリは無かったことにして続きを続行させるしかありません。
このクエリが実行された事実だけをジャンプする。

覆水盆にキング・クリムゾン。
焦げたパンなんてなかった。

「お前は矢に拒否されたんだァァァーッ！」って叫びながら、こんなコマンドを実行します。

mysql> SET GLOBAL SQL_SLAVE_SKIP_COUNTER = 1;
Query OK, 0 rows affected (0.03 sec)

エラーの時間が一度だけ「消飛ぶ」ッ！

そしてレプリケーションを再開してみます。

mysql> START SLAVE SQL_THREAD;
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: 123.45.6.789
Master_User: repl
Master_Port: 3306
Connect_Retry: 60
Master_Log_File: mysqld-bin.003755
Read_Master_Log_Pos: 740738305
Relay_Log_File: mysqld-relay-bin.004023
Relay_Log_Pos: 672976825
Relay_Master_Log_File: mysqld-bin.003748
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table: resaku_count
Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 672976678
Relay_Log_Space: 8256939644
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: 56508
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: 499
1 row in set (0.00 sec)

master、slaveともにYes、Yes、Yes。

Slave_IO_Running: Yes
Slave_SQL_Running: Yes

動いているってことです。

さてそして、slaveのレプリケーションが止まっている間も、masterは動き続けていたわけです。
凄いですよね。slave(奴隷)がサボっている間も、master(主人)は黙々と働き続けていたわけです。
ということは、両者の間に時間差がある訳です。
つまりslaveに取り込まれていない、master側のデータが溜まっているはずです。
それは上記のSHOW SLAVE STATUSの結果に載っていました。
どれだけ「時間は止まっていた」のでしょうか？見てみましょう。

「ザ・ワールド」ッ！(ﾄﾞｫｫｫﾝ)

Seconds_Behind_Master: 56508

56508秒。
15時間41分48秒。

長いわ！
「これから静止時間15時間41分48秒のうちにカタを付けるッ！」って十分だぜ承太郎！

そもそもなぜこんな長時間障害が放置されていたの？という気持ちをグッっとこらえて作業作業。
我々は皆、運命の奴隷（slave）なのです。

それにしてもmaster(主人)とかslave(奴隷)とか酷い用語ですよね。
サッカーのサドンデスとか自殺点みたいに、違う用語に置き換えてあげたい気がします。

maid（メイド）とかダメですかね？

master(主人)とslave(奴隷)だと、エジプトあたりでムチ打たれながらピラミッドの石運んでる感じで嫌です。
ところがそれがmaster(ご主人様)とmaid(メイド)になるとあら不思議、とっても優しい世界。

さてこの15時間、どうやって取り戻すのでしょう？
15時間待っていれば良い？
いやいや、その間もサービスは動いているのですから、masterからslaveにデータが送り続けられてきます。
ということは15時間の差は絶対に埋まらない？
そんなことはありません。

slaveは時を加速して追いつくのです。

「時は加速する」ッ！
どのようにご主人様に追いついたのか、実際の記録を公開します。
皆で「時の再加速」を追体験しましょう。
それでは行きます！

「maid・イン・ヘブン」ッ！

10:00頃・・・レプリケーション再開
56508秒(15時間41分)

10：40・・・アナスイ、徐倫との結婚許可を求める（承太郎却下）
52786秒（14時間39分）

10：50・・・海に入る。
50931秒（14時間08分）

11：00・・・重い処理が走って時間差が開く。
51526秒（14時間18分）

11：20・・・「2手・・・遅かったな・・・」
51002秒（14時間10分）

10：30・・・承太郎、エルメェス死亡
46190秒（12時間49分）

12：00・・・徐倫死亡
36355秒（10時間05分）

13：00・・・特異点
30980秒（8時間36分）

14：20・・・ぼくの名前はエンポリオです
0秒(追いついた)

15時間の差を4時間20分で取り戻したことになります。
（その間の経過時間も含めると19時間を4時間で取り戻すことが可能ということですね。もちろんサーバスペックや回線速度、なによりもデータ量によってこの結果は大幅に変わることでしょう）

ちなみにこんなに待つのが嫌な場合、別の方法もあります。
というよりむしろこっちが本筋かもしれませんが。それは
１．masterを停止する
２．masterデータをdumpする
３．dumpをslaveに叩き込む
４．show slave statusの結果をもとに、こんな感じのを実行する。

CHANGE MASTER TO MASTER_HOST=’123.45.6.789′,
MASTER_USER=’repl’,
MASTER_PASSWORD=”,
MASTER_LOG_FILE=’mysqld-bin.003748′,
MASTER_LOG_POS=714615665;

つまり物理的にmasterとslaveを同じにして、ほんの少しの差の部分からレプリケーションを再開するということです。
しかし

１．masterを停止する　←運用中のサービスを停止する必要あり！ユーザアナウンスとか対応とか大変かも！っていうか大変！
２．masterデータをdumpする　←超重いかも！時間かかるかも！
３．dumpをslaveに叩き込む　←超重いかも！時間かかるかも！import失敗するかも！
４．show slave statusの結果をもとに、こんな感じのを実行する。　←開始位置合ってるか不安かも！

なのでよほどの事情がなければ、個人的には「メイド・イン・ヘブン」がいいんじゃないかなあと思うのですよ。

さて、とりあえずは解決したように見えますが、「そもそもなぜレプリケーションは止まったのか？」を突き止めないうちは、本当の解決にはなりません。

レプリケーションが止まった原因は

続く

途中でジョジョネタを絡めたら長文になってしまいました（汗
狙ってるわけではないのですが、なんか次から次へとネタが浮かび、それが本文のテーマと絶妙にリンクして止まらなくなった・・・