2019年7月26日金曜日

MySQLが刺さった時にざっと見るためのメモ

TL;DR

  • mysqldが 本当に 刺さって動作を停止している時のためのメモです。重いだけの時に使うものじゃない。
  • ざっと見る方法であって、解決方法じゃない。

まずは慌てず騒がずエラーログを見る。クラッシュしてるログが出てるならそれはそれでOK。mysqld_safe とか systemd を使っている場合、 mysqld が自動再起動されているかも知れない。クラッシュリカバリーの真っ最中はプロセスが浮いていても接続できないので、クラッシュリカバリー中だったら見守る。
OOM Killerに殺された場合はエラーログに何も出ずにsyslogだけ吐くので、 /var/log/messages あたりもチラ見しておくと吉。
特にクラッシュはしていないようであれば、 dstat でCPU使用率やDisk書き込み、IOPSあたりを見る。
Disk書き込み量やIOPSがガリガリ増えているなら、datadirにでもいって ls -ltr とかで更新がされてるかどうか見る。バイナリーログやInnoDBログが更新されているなら、刺さっててもまだ何かしている(=そのまま kill -9 でバッサリやると設定によってはファイルが壊れる)可能性がある。
設定によってはここでコアファイルをガリガリ書いている最中かも知れない。
その場合、ストレージ容量を食い破られないようにだけ注意(コアを吐き終わるまでmysqldが終了せず、コアは容量が足りなくて吐けず…でいつまでも終わらない)。
食い破られそうなら mysqldkill -9 で仕留めるしかない。
Diskが何も書いてなさげでCPUだけ回っているならバッファプール周りで何か起こっていそうな予感。体感ではチェンジバッファとかページクリーナーがぐるぐるしていることが多い。 poor man’s profiler やPercona Toolkit化された pt-pmp で見てもいいけど、見たところで多分幸せにはならない(解決方法はわからないから)
ただこのケースは kill -9 でも壊れる可能性は低い(体感)、ただしMyISAMとMroonga、オメーは別だ。
解析のためにコアファイルを取りたければ ulimit -c とかabrtdの設定を確認してから kill -6 。容量には注意。見かけ上のサイズにVSZ、実容量でRSSを取る。
Diskにも書いてないしCPUも回っていないことがまれにだがよくある(特に5.7でデカめのインスタンスに mysqladmin shutdown を放り投げたあと…)が、その場合はなんか変なところで刺さっているんだろう…コア取ったりpt-pmpでスタックトレースを送り付けた方がいいかも知れない。
復旧(InnoDBのみ、安全なパラメーター、クラッシュリカバリーが成功していればプロセスを起動するだけでもいい)させたら今度は中身を見ていく。バックアップや他のスレーブからデータをコピーしてくる場合、エラーログをどこかに残しておかないと追うことも出来なくなるので注意。
基本はエラーログ。綺麗に(?)クラッシュしてる場合は “mysqld got signal x” のログがあるはず。これが無くていきなりプロセスが消えている場合はOOM Killerに殺された可能性が高い。
06:37:30 UTC - mysqld got signal 6 ;
Dive into MySQL Error - Speaker Deck でしゃべったけれど、 “signal 6” はアサーション(主にInnoDB)、 “signal 11” はバグな傾向がある。
“This could be because you hit a bug.” って書いてあるけどこれは単なるハードコード文なので真に受けてはいけない。
再起動しようとしてまた “signal 6” で落ちるなら、InnoDBのデータが破損している気がする。エラーログに含まれるスタックトレースの中にinnobaseな関数が並んでたりすると更に確率が上がる。
何度起動しようとしても “signal 11” で落ち 続ける ならデータが壊れている && そのエラーハンドルにバグがある予感。datadirをまるっとコピーしてバグレポートできると吉。
どっちのシグナルにしろ起動したら上がっちゃったなら、ハードウェアの一過性の障害という可能性もある。 dmesg やハードウェアのログも見るのを忘れずに。あとは mysqlcheck --all-databases とかしておくといいかも知れない。
……っていうのを某氏向けに書いていたんだけどすっかり時期を逸したので、ここでおとむらい。

MySQL 8.0.17のCLONE INSTANCE FROMを使うとすごく楽にレプリケーションスレーブが作れる

TL;DR

  • 日々の覚書: MySQL 8.0.17でついにCloneプラグインが入った で紹介した CLONE LOCAL DATA は現在のdatadirをローカルのファイルシステムに一貫性のある形でコピーするステートメントだった
  • これをスレーブになるサーバーに転送してやってももちろん良いんだけど、そこまで一括でやってくれる CLONE INSTANCE FROM のステートメントも存在する
  • スレーブ増やすのが捗る

CLONE INSTANCE FROM を使うためには、データのコピー元( ドキュメント 上では ドナー(Donor) )とコピー先(同 レシピエント(Recipient) )それぞれのMySQLでCloneプラグインが有効化されていないといけない。
donor> INSTALL PLUGIN clone SONAME 'mysql_clone.so';
recipient> INSTALL PLUGIN clone SONAME 'mysql_clone.so';
ちなみにレシピエントでCloneプラグインが有効になってないとそもそもCLONEステートメントが転けるし、
recipient> CLONE INSTANCE FROM cloner@127.0.0.1:12345 IDENTIFIED BY '';
ERROR 1524 (HY000): Plugin 'clone' is not loaded
ドナーで有効になっていないと
recipient> CLONE INSTANCE FROM cloner@127.0.0.1:12345 IDENTIFIED BY '';
ERROR 3862 (HY000): Clone Donor Error: 1524 : Plugin 'clone' is not loaded.
とそれぞれ違うエラーが出る(レシピエントとしてのエラー3862と、ドナーが返したであろうエラーの1524が1つのメッセージに混じっていてちょっと面白い)
Cloneプラグインを両方で有効化したら、ドナーになるインスタンスでアカウントを作成する。必要になる権限は BACKUP_ADMIN のみ。ここは CLONE LOCAL DATA の時といっしょ。
donor> CREATE USER clone_user;
Query OK, 0 rows affected (0.01 sec)

donor> GRANT BACKUP_ADMIN ON *.* TO clone_user;
Query OK, 0 rows affected (0.00 sec)
レシピエント側で CLONE INSTANCE FROM を実行する。ユーザー名、ホスト名やIPアドレス、ポートの部分は クォートしない ( CHANGE MASTER TO はクォートしないといけないのに…)、パスワードを設定していなくても(そんなことがあるのか) IDENTIFIED BY .. はつけないと構文エラーになる、あたりが注意点。
ポート番号も、デフォルトの3306でも省略できずちゃんとフルで書かないとシンタックスエラーって言われる。
recipient> CLONE INSTANCE FROM clone_user@172.17.0.10:3306 IDENTIFIED BY '';
ERROR 3869 (HY000): Clone system configuration: 172.17.0.10:3306 is not found in clone_valid_donor_list:
おっとエラー。
CLONE INSTANCE FROM で指定する先は clone_valid_donor_list というパラメーターにセットしてやらないといけない。
recipient> SET GLOBAL clone_valid_donor_list = '172.17.0.10:3306';
Query OK, 0 rows affected (0.00 sec)

recipient> CLONE INSTANCE FROM clone_user@172.17.0.10:3306 IDENTIFIED BY '';
これでデータのコピーが始まる。
コピーが終わると勝手に RESTART ステートメントが走っておしまい。
RESTART の条件である「 mysqld_safesystemd にぶら下がっていること」が満たされてないとシャットダウンだけするっぽい)
再起動してきたら、 performance_schema.clone_status あたりからbinlogの情報とかgtid_executedとかが拾えるのでいつも通り CHANGE MASTER TO でレプリケーションを構成してやればスレーブが出来上がる。
レプリケーション用のアカウントとかはよしなに今までと同じ感じで作っておく。
donor> use performance_schema
Database changed

donor> show tables like '%clone%';
+----------------------------------------+
| Tables_in_performance_schema (%clone%) |
+----------------------------------------+
| clone_progress                         |
| clone_status                           |
+----------------------------------------+
2 rows in set (0.01 sec)

donor> SELECT * FROM clone_status;
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
| ID   | PID  | STATE     | BEGIN_TIME              | END_TIME                | SOURCE          | DESTINATION    | ERROR_NO | ERROR_MESSAGE | BINLOG_FILE   | BINLOG_POSITION | GTID_EXECUTED                                                                             |
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
|    1 |    0 | Completed | 2019-07-26 10:49:46.370 | 2019-07-26 11:01:59.458 | 172.17.0.10:3306 | LOCAL INSTANCE |        0 |               | binlog.000003 |             155 | 7470a831-4aed-11e9-b334-70106f4f8c56:1-8218993,
ee20abe3-33e8-11e9-8a63-1c98ec2973a4:1-16 |
+------+------+-----------+-------------------------+-------------------------+-----------------+----------------+----------+---------------+---------------+-----------------+-------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

donor> CHANGE MASTER TO master_host= '172.17.0.1', master_port= 3306, master_user = 'replicator', master_password= '', master_log_file= 'binlog.000003', master_log_pos= 155;
gtid_mode=ON ならもっと楽ですね! 捗る!!!

2019年7月24日水曜日

MySQL 8.0.17でついにCloneプラグインが入った

TL;DR


取り敢えず CLONE LOCAL DATA の方。
準備は INSTALL PLUGIN で一発。
mysql80 35> INSTALL PLUGIN CLONE SONAME "mysql_clone.so";
Query OK, 0 rows affected (0.01 sec)

mysql80 35> SHOW PLUGINS;
+---------------------------------+----------+--------------------+-----------------+---------+
| Name                            | Status   | Type               | Library         | License |
+---------------------------------+----------+--------------------+-----------------+---------+
..
| clone                           | ACTIVE   | CLONE              | mysql_clone.so  | GPL     |
+---------------------------------+----------+--------------------+-----------------+---------+
46 rows in set (0.00 sec)
使い方も簡単。 CLONE LOCAL DATA DIRECTORY /tmp/clone とかこれだけ。
ディレクトリーは書き込み権限があれば大丈夫。 CLONE LOCAL DATA ステートメントを実行するアカウントには BACKUP_ADMIN 権限が要るが、それ以外(たとえば、グローバルSELECTとかFLUSHとか)は要らない。
mysql80 35> create user yoku0825;
Query OK, 0 rows affected (0.01 sec)

mysql80 35> grant backup_admin on *.* TO yoku0825;
Query OK, 0 rows affected (0.00 sec)

mysql80 70> SHOW GRANTS;
+---------------------------------------------+
| Grants for yoku0825@%                       |
+---------------------------------------------+
| GRANT USAGE ON *.* TO `yoku0825`@`%`        |
| GRANT BACKUP_ADMIN ON *.* TO `yoku0825`@`%` |
+---------------------------------------------+
2 rows in set (0.00 sec)

mysql80 70> CLONE LOCAL DATA DIRECTORY '/tmp/clone';
Query OK, 0 rows affected (3.66 sec)
tpcc_start -u tpcc -w 10 -S /usr/mysql/8.0.17/data/mysql.sock -d tpcc -l 1200 -r 0 しながらローカルクローンしてみる。
mysql80 35> CLONE LOCAL DATA DIRECTORY '/tmp/clone';
Query OK, 0 rows affected (7.78 sec)

$ ll /tmp/clone
total 161804
drwxr-x--- 2 yoku0825 yoku0825       85 Jul 24 18:31 #clone
drwxr-x--- 2 yoku0825 yoku0825       19 Jul 24 18:31 d1
-rw-r----- 1 yoku0825 yoku0825 12582912 Jul 24 18:31 ibdata1
-rw-r----- 1 yoku0825 yoku0825 50331648 Jul 24 18:31 ib_logfile0
-rw-r----- 1 yoku0825 yoku0825 50331648 Jul 24 18:31 ib_logfile1
drwxr-x--- 2 yoku0825 yoku0825        6 Jul 24 18:31 mysql
-rw-r----- 1 yoku0825 yoku0825 24117248 Jul 24 18:31 mysql.ibd
drwxr-x--- 2 yoku0825 yoku0825       27 Jul 24 18:31 sys
drwxr-x--- 2 yoku0825 yoku0825     4096 Jul 24 18:31 tpcc
-rw-r----- 1 yoku0825 yoku0825 14680064 Jul 24 18:31 undo_001
-rw-r----- 1 yoku0825 yoku0825 13631488 Jul 24 18:31 undo_002

$ du -sh /tmp/clone
1.1G    /tmp/clone
その間のCommit per Secはこんな感じになった。
2019-07-24 18:30:33     value:0/1s      variable_name:Handler_commit
2019-07-24 18:30:34     value:3365/1s   variable_name:Handler_commit
2019-07-24 18:30:35     value:4616/1s   variable_name:Handler_commit
2019-07-24 18:30:36     value:5040/1s   variable_name:Handler_commit
2019-07-24 18:30:37     value:5043/1s   variable_name:Handler_commit
2019-07-24 18:30:38     value:4081/1s   variable_name:Handler_commit
2019-07-24 18:30:39     value:5448/1s   variable_name:Handler_commit
2019-07-24 18:30:40     value:4167/1s   variable_name:Handler_commit
2019-07-24 18:30:41     value:5259/1s   variable_name:Handler_commit
2019-07-24 18:30:42     value:4897/1s   variable_name:Handler_commit
2019-07-24 18:30:43     value:4807/1s   variable_name:Handler_commit
2019-07-24 18:30:44     value:5556/1s   variable_name:Handler_commit
2019-07-24 18:30:45     value:5892/1s   variable_name:Handler_commit
2019-07-24 18:30:46     value:5263/1s   variable_name:Handler_commit
2019-07-24 18:30:47     value:5093/1s   variable_name:Handler_commit
2019-07-24 18:30:48     value:5727/1s   variable_name:Handler_commit
2019-07-24 18:30:49     value:5506/1s   variable_name:Handler_commit
2019-07-24 18:30:50     value:5612/1s   variable_name:Handler_commit
2019-07-24 18:30:51     value:6066/1s   variable_name:Handler_commit
2019-07-24 18:30:52     value:4491/1s   variable_name:Handler_commit
2019-07-24 18:30:53     value:4460/1s   variable_name:Handler_commit
2019-07-24 18:30:54     value:4901/1s   variable_name:Handler_commit
2019-07-24 18:30:56     value:4807/1s   variable_name:Handler_commit
2019-07-24 18:30:57     value:5649/1s   variable_name:Handler_commit
2019-07-24 18:30:58     value:4307/1s   variable_name:Handler_commit
2019-07-24 18:30:59     value:4661/1s   variable_name:Handler_commit
2019-07-24 18:31:00     value:4864/1s   variable_name:Handler_commit
2019-07-24 18:31:01     value:5460/1s   variable_name:Handler_commit
2019-07-24 18:31:02     value:4245/1s   variable_name:Handler_commit
2019-07-24 18:31:03     value:4109/1s   variable_name:Handler_commit
2019-07-24 18:31:04     value:1661/1s   variable_name:Handler_commit <-- CLONE LOCAL DATA開始
2019-07-24 18:31:05     value:1950/1s   variable_name:Handler_commit
2019-07-24 18:31:06     value:2399/1s   variable_name:Handler_commit
2019-07-24 18:31:07     value:2168/1s   variable_name:Handler_commit
2019-07-24 18:31:08     value:2121/1s   variable_name:Handler_commit <-- CLONE LOCAL DATA終了
2019-07-24 18:31:09     value:4773/1s   variable_name:Handler_commit
2019-07-24 18:31:10     value:4563/1s   variable_name:Handler_commit
2019-07-24 18:31:11     value:4592/1s   variable_name:Handler_commit
2019-07-24 18:31:12     value:5245/1s   variable_name:Handler_commit
2019-07-24 18:31:13     value:4650/1s   variable_name:Handler_commit
2019-07-24 18:31:14     value:5380/1s   variable_name:Handler_commit
2019-07-24 18:31:15     value:4874/1s   variable_name:Handler_commit
2019-07-24 18:31:16     value:4629/1s   variable_name:Handler_commit
2019-07-24 18:31:17     value:4493/1s   variable_name:Handler_commit
優秀なのでは!?
エラーログはこんな感じに出てた。Noteなので log_error_verbosity= 3 が必要。
2019-07-24T18:31:03.279399+09:00 35 [Note] [MY-013457] [InnoDB] Clone Begin Master Task by root@localhost
2019-07-24T18:31:03.279482+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply Master Loop Back
2019-07-24T18:31:03.279494+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply Begin Master Task
2019-07-24T18:31:03.279727+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 1
2019-07-24T18:31:03.279749+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:03.279779+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 1
2019-07-24T18:31:03.279793+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN FILE COPY
2019-07-24T18:31:03.295060+09:00 35 [Note] [MY-011845] [InnoDB] Clone Start PAGE ARCH : start LSN : 1354569844, checkpoint LSN : 13458
13923
2019-07-24T18:31:03.295198+09:00 35 [Note] [MY-013458] [InnoDB] Clone State FILE COPY : 25 chunks,  chunk size : 64 M
2019-07-24T18:31:03.295584+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 1
2019-07-24T18:31:03.295609+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FILE COPY:
2019-07-24T18:31:03.295674+09:00 35 [Note] [MY-011978] [InnoDB] Clone estimated size: 1.00 GiB Available space: 3.06 GiB
2019-07-24T18:31:03.775468+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 20% completed.
2019-07-24T18:31:04.884874+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 40% completed.
2019-07-24T18:31:06.387871+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 60% completed.
2019-07-24T18:31:07.846118+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 80% completed.
2019-07-24T18:31:08.347343+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Tune Threads from: 1 to: 2 prev: 1 target: 2.'
2019-07-24T18:31:08.348284+09:00 0 [Note] [MY-013457] [InnoDB] Clone Begin Task ID: 1
2019-07-24T18:31:08.348325+09:00 0 [Note] [MY-013457] [InnoDB] Clone Apply Begin Task ID: 1
2019-07-24T18:31:08.521355+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 928 MiB @ 177 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:08.521409+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 2
2019-07-24T18:31:08.521428+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:08.521444+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:08.521455+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN PAGE COPY
2019-07-24T18:31:08.544317+09:00 35 [Note] [MY-011840] [InnoDB] Clone Start LOG ARCH : start LSN : 1347785138
2019-07-24T18:31:08.544373+09:00 35 [Note] [MY-011846] [InnoDB] Clone Stop  PAGE ARCH : end   LSN : 1347785138, log sys LSN : 1355428039
2019-07-24T18:31:08.544804+09:00 35 [Note] [MY-013458] [InnoDB] Clone State PAGE COPY : 1551 pages, 78 duplicate pages, 1 chunks,  chunk size : 64 M
2019-07-24T18:31:08.646061+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:08.646130+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State PAGE COPY:
2019-07-24T18:31:10.222406+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 100% completed.
2019-07-24T18:31:10.222447+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 952 MiB @ 137 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:10.222461+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 3
2019-07-24T18:31:10.222470+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:10.222480+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:10.222487+09:00 35 [Note] [MY-013458] [InnoDB] Clone State BEGIN REDO COPY
2019-07-24T18:31:10.340523+09:00 35 [Note] [MY-011841] [InnoDB] Clone Stop  LOG ARCH : end LSN : 1356084650
2019-07-24T18:31:10.340576+09:00 35 [Note] [MY-013458] [InnoDB] Clone State REDO COPY : 3 chunks,  chunk size : 64 M
2019-07-24T18:31:10.442258+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:10.442296+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State REDO COPY:
2019-07-24T18:31:10.450725+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 33% completed.
2019-07-24T18:31:10.450778+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 66% completed.
2019-07-24T18:31:10.450791+09:00 35 [Note] [MY-013458] [InnoDB] Stage progress: 100% completed.
2019-07-24T18:31:10.550946+09:00 35 [Note] [MY-013272] [Clone] Plugin Clone reported: 'Client: Total Data: 960 MiB @ 132 MiB/sec, Network: 0 MiB @ 0 MiB/sec.'
2019-07-24T18:31:10.550995+09:00 35 [Note] [MY-013458] [InnoDB] Clone set state change ACK: 4
2019-07-24T18:31:10.551009+09:00 35 [Note] [MY-013458] [InnoDB] Clone Master received state change ACK
2019-07-24T18:31:10.551019+09:00 35 [Note] [MY-013458] [InnoDB] Clone State Change : Number of tasks = 2
2019-07-24T18:31:10.551026+09:00 35 [Note] [MY-013458] [InnoDB] Clone State DONE
2019-07-24T18:31:10.654535+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State Change : Number of tasks = 2
2019-07-24T18:31:10.654584+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FLUSH DATA:
2019-07-24T18:31:10.697683+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State FLUSH REDO:
2019-07-24T18:31:11.015694+09:00 35 [Note] [MY-013458] [InnoDB] Clone Apply State DONE
2019-07-24T18:31:11.059224+09:00 0 [Note] [MY-013457] [InnoDB] Clone Apply End Task ID: 1 Passed, code: 0:
2019-07-24T18:31:11.059277+09:00 0 [Note] [MY-013457] [InnoDB] Clone End Task ID: 1 Passed, code: 0:
2019-07-24T18:31:11.059677+09:00 35 [Note] [MY-013457] [InnoDB] Clone Apply End Master Task ID: 0 Passed, code: 0:
2019-07-24T18:31:11.059910+09:00 35 [Note] [MY-013457] [InnoDB] Clone End Master Task ID: 0 Passed, code: 0:
取り敢えず感動をお伝えしたかった。