Shooting a trouble of MySQL

Shooting a trouble of MySQL 今日も今日とてマイエスキューエる 2019/09/26 yoku0825 db tech
showcase Tokyo 2019

＼こんにちは／ yoku0825＠とある企業のDBA オラクれない ‐ ポスグれない ‐ マイエスキューエる ‐ 生息域 Twitter:
@yoku0825 ‐ Blog: 日々の覚書 ‐ 日本MySQLユーザ会 ‐ MySQL Casual ‐ 1/87

Shooting a trouble of MySQL MySQLに「つながらない」「どう」「つながらない」のかを切り分ける 2/87

SSHから DBサーバーに対する接続性を確認する OSのハングアップでは ping や TCP SYN , SNMP などは
応答されてしまうケースがあるので、その後の操作も兼ねて ssh が一番確実 ‐ DBサーバーでシェルが使えない場合は成功したつもりになって飛ばすしかない ‐ $ ssh db-server .. 3/87

DBサーバーにSSHログインできた？できないネットワークに異常はない？サーバーをハードウェア的に調査？いずれにせよ一旦この資料のスコープの外に出ます（ハコが復旧したら戻ってきてください）できる切り分けは続く 4/87

HA用のミドルウェアをなにがしか使っている場合 MHA for MySQL, mikasafabric for MySQL, MMM, Orchestrator, ..
この時点でそのサーバーの電源を落とす方が二次被害が起こるリスクを減らせる死にかけのサーバーがフェイルオーバープロセスを噛んじゃってフェイルオーバーが進まない ‐ 折角マスターのフェイルオーバーに成功したのに、旧マスターがゾンビのように生き続けていて一部サーバーはそちらに書き込んでしまった ‐ ロードバランサーの分散に入ったり外れたりを繰り返してサービスが不安定になった ‐ 5/87

トラブル箇所の切り分けローカルホストのMySQL接続はできる？ソケットファイル接続または 127.0.0.1 への接続 ‐ シェルが取れない場合はリモートホストからやるしかないけれど ‐ $ mysql
-h localhost -S /var/lib/mysql/mysql.sock -u root -p または $ mysql -h 127.0.0.1 -P 3306 -u root -p 6/87

ローカルホストのMySQL接続はできた？できない次ページからの解説へできる切り分けは続く 7/87

ローカルホストのMySQL接続ができない ERROR 2002 (HY000): Can't connect to local MySQL server
through socket '/var/lib/mysql/my sql.sock' (2) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (111) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (110) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (4) ERROR 1045 (28000): Access denied for user 'root'@'127.0.0.1' (using password: NO) ERROR 1040 (08004): Too many connections ERROR 3032 (HY000): The server is currently in offline mode etc.. 8/87

エラーコードに注目する ERROR 2002 (HY000): Can't connect to local MySQL server
through socket '/var/lib/mysql/my sql.sock' (2) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (111) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (110) ERROR 2003 (HY000): Can't connect to MySQL server on '127.0.0.1' (4) ERROR 1045 (28000): Access denied for user 'root'@'127.0.0.1' (using password: NO) ERROR 1040 (08004): Too many connections ERROR 3032 (HY000): The server is currently in offline mode etc.. mysql コマンドラインクライアントが接続に失敗した時の出力のフォーマットは、 MySQLのエラーコード + SQLSTATE + エラーメッセージ + OSのエラーコード SQLSTATEは切り分けには重要でないので以降割愛 ‐ 9/87

エラーコードに注目する ERROR 2002 (HY000): Can't connect to local MySQL server
through socket '/var/lib/mysql/my sql.sock' (2) MySQLエラーコード: 2002 エラーメッセージ: Can't connect to local MySQL server through socket '/var/ lib/mysql/mysql.sock' OSエラーコード: 2 Linuxでは 2 = ENOENT = No such file or directory ‐ 10/87

エラーコードに注目する ERROR 2003 (HY000): Can't connect to MySQL server on
'127.0.0.1' (111) MySQLエラーコード: 2003 エラーメッセージ: Can't connect to MySQL server on '127.0.0.1' OSエラーコード: 111 Linuxでは 111 = ECONNREFUSED = Connection refused ‐ 11/87

'127.0.0.1' (110) MySQLエラーコード: 2003 エラーメッセージ: Can't connect to MySQL server on '127.0.0.1' OSエラーコード: 110 Linuxでは 110 = ETIMEDOUT = Connection timed out ‐ 12/87

'127.0.0.1' (4) MySQLエラーコード: 2003 エラーメッセージ: Can't connect to MySQL server on '127.0.0.1' OSエラーコード: 4 Linuxでは 4 = EINTR = Interrupted system call ‐ 13/87

エラーコードに注目する ERROR 1045 (28000): Access denied for user 'root'@'127.0.0.1' (using
password: NO) MySQLエラーコード: 1045 エラーメッセージ: Access denied for user 'root'@'127.0.0.1' (using password: NO) OSエラーコード: なし 14/87

エラーコードに注目する ERROR 1040 (08004): Too many connections MySQLエラーコード: 1040 エラーメッセージ:
Too many connections OSエラーコード: なし 15/87

エラーコードに注目する ERROR 3032 (HY000): The server is currently in offline
mode MySQLエラーコード: 3032 エラーメッセージ: The server is currently in offline mode OSエラーコード: なし 16/87

エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサイドエラー」 17/87

エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」クライアントサイドエラーは基本的に「接続できなかった」「接続できそうだけどできなかった」「接続できたけどダメだった」くらいの情報しかない ‐ クライアントサイドエラーとOSエラーコードはセットで表示されることが多い ‐ それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサイドエラー」 18/87

エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサイドエラー」 MySQLプロトコルにおいてサーバーサイドエラーはERRパケットを通じてサーバーから明示的に送信される ‐ サーバーサイドエラーが返ってきているなら、mysqldそのものの障害ではない可能性が高い ‐
19/87

サーバーサイドエラー ERROR 1045 (28000): Access denied for user 'root'@'127.0.0.1' (using
password: NO) MySQLエラーコード: 1045 エラーメッセージ: Access denied for user 'root'@'127.0.0.1' (using password: NO) OSエラーコード: なし 20/87

サーバーサイドエラー ERROR 1040 (08004): Too many connections MySQLエラーコード: 1040 エラーメッセージ:
Too many connections OSエラーコード: なし 21/87

ローカルホストのMySQL接続はできた…けど取り敢えず SHOW PROCESSLIST かな FULL はお好みで ‐ mysql> SHOW
PROCESSLIST; 22/87

SHOW PROCESSLISTから読み解くもの mysql> SHOW PROCESSLIST; .. 4 rows in set
(0.00 sec) 取り敢えず一発目はログが流れても構わないので最後の n rows in set を見ましょうそれがほぼ（レプリケーション関連のスレッドやINSERT Delayedスレッド、イベントスケジューラーなどを含むが大体は数が小さいので無視して構わない）現在の接続中（接続シーケンス中のクライアントコネクションも含むが、 max_connections とかは接続シーケンス中のものも含むので問題ないはず）のコネクションの数になる 23/87

SHOW PROCESSLISTから読み解くもの mysql> SHOW PROCESSLIST; .. 4 rows in set
(0.00 sec) n rows in set を見た時に、 max_connections の値に対して余裕があるか？ ‐ 数回叩いても平常時と比べて非常に高い/低い値をさまよっていないか？ ‐ 24/87

SHOW PROCESSLISTから更に読み解くものスリープしてるコネクションを除外して表示させる mysql> pager grep -v Sleep mysql> SHOW
PROCESSLIST; .. 4 rows in set (0.00 sec) 25/87

SHOW PROCESSLISTから更に読み解くもの mysql> pager grep -v Sleep mysql> SHOW PROCESSLIST;
.. 4 rows in set (0.00 sec) ざっとスリープ以外の出力結果を見た時に、バックグラウンドスレッド以外で Time が異様に大きいクエリーはないか？ ‐ Info には実行中のクエリーが表示されるが、似たようなクエリーが並んでいないか？ ‐ 26/87

Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比較的低いスレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有するメモリーは案外大きく影響を受けることがある 28/87

Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比較的低いただしもちろんコア数が少なかったり重いクエリーが多重で流されるとCPUを食い尽くすことも ‐ スレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有するメモリーは案外大きく影響を受けることがある
29/87

Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比較的低いスレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有するメモリーは案外大きく影響を受けることがあるテンポラリーテーブルを使うSELECT は書き込みを行うことがよくある ‐ InnoDBバッファプールはスレッド間で共有される ‐
30/87

Infoに似たようなクエリーが並ぶ特に INSERT, UPDATE, DELETE や SELECT .. FOR UPDATE
の排他ロックを取るクエリーロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソースをそこそこ食っていて… 31/87

の排他ロックを取るクエリーロックの競合自体は「データベースの整合性」を保つために DBMSが備えた機能 ‐ MySQL側にもロック待ちのタイムアウト（主に innodb_lock_wait_timeout, デフォルト50秒）は設定できるが、タイムアウトするまでの間APサーバーはコネクションを維持したまま待たなくてはいけないので、APサーバーはその間新たなリクエストを受け止め続けなくてはいけなくなる lock_wait_timeout, innodb_lock_wait_timeout を十分短く設定するか、APサーバー側でもタイムアウトを設定するか APサーバー側でタイムアウトした場合、MySQLのコネクションをちゃんとクローズしてくれるかどうかは実装依存 ‐ ロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソースをそこそこ食っていて… 32/87

の排他ロックを取るクエリーロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソースをそこそこ食っていて… 典型的なパターンは「テーブルスキャンあるいは大量レコード」「バッファプールにデータが乗り切っている」「テンポラリーテーブルを使っている」 ‐ リソースに余裕がある間はそれなりの速度で応答を返せるものの、一定以上のアクセスが集中するとサチる ‐ 33/87

SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッションを KILL すれば暫定復旧するはずただの SELECT に見えても実はそれがトランザクションの一部で、 KILL
したら大量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない限りは無限にクエリーが積もり続ける可能性がある 34/87

SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッションを KILL すれば暫定復旧するはず KILL QUERY で停止しても
トランザクションはロールバックされるとは限らない（アプリケーション依存） ‐ KILL でトランザクションごとロールバックしたとしても、再実行はどうするか…？ ‐ ただの SELECT に見えても実はそれがトランザクションの一部で、 KILL したら大量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない限りは無限にクエリーが積もり続ける可能性がある 35/87

SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッションを KILL すれば暫定復旧するはず単発の SELECT に見えても実はそれがトランザクションの一部で、 KILL
したら大量ロールバックが走る可能性がある SHOW ENGINE INNODB STATUS TRANSACTIONSセクションの MySQL thread id %d と突き合わせて、 undo log entries の値を確認する ‐ ロールバックは更新よりも重い処理なので、今後の処理の流れが見通せるなら「待った方が結果的に復旧が速い」ことは十分ある ‐ APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない限りは無限にクエリーが積もり続ける可能性がある 36/87

SHOW ENGINE INNODB STATUSのTRANSACTIONSセクション mysql> SHOW ENGINE INNODB STATUS\G ..
------------ TRANSACTIONS ------------ Trx id counter 22588 Purge done for trx's n:o < 22588 undo n:o < 0 state: running but idle History list length 678 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0, not started MySQL thread id 2, OS thread handle 0x7f6bd0094700, query id 13 localhost root init show engine innodb status ---TRANSACTION 22275, ACTIVE 1397 sec rollback ROLLING BACK 542497 lock struct(s), heap size 64420280, 100542496 row lock(s), undo log entries 52 636267 MySQL thread id 1, OS thread handle 0x7f6bd00d5700, query id 8 localhost root init ROLLBACK -------- FILE I/O -------- .. 37/87

SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッションを KILL すれば暫定復旧するはずただの SELECT に見えても実はそれがトランザクションの一部で、 KILL
したら大量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない限りは無限にクエリーが積もり続ける可能性があるワンライナーでそれっぽいクエリーを KILL し続けながら、AP側への修正がリリースされるのを待ち続ける ‐ 38/87

切り分けは大事監視の段階で切り分けまでざっくり済ませられるようだと対応速度が上がる ytkit - Yoku-san no ToolKIT に yt-healthcheck として実装・公開
‐ 長時間実行が続いているクエリーの監視、コネクション数 / max_connections の割合の監視、テーブルの AUTOINC の値のパーセンテージの監視… およびそれらの閾値に引っ掛かった時の、 SHOW FULL PROCESSLIST や SHOW ENGINE INNODB STATUS の情報をファイルに出力して保全しておく機能 ‐ 39/87

ひとやすみ 40/87

今北産業 mysqldプロセスが生きていてリソースに問題がありそうな場合のトラブルシュートをなぞってきた次はmysqldプロセスが生きていない/ハングアップしている場合のトラブルシュート ( ´-｀).oO（あっ、2行だ 41/87

mysqldプロセスが停止していた場合停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップからリストアするなり何なりが必要
‐ 停止した原因を探す 42/87

mysqldプロセスが停止していた場合停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性正常停止しなかった場合のマスターとスレーブのデータの整合性は自分で保証しなければならない ‐
MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップからリストアするなり何なりが必要 ‐ 停止した原因を探す 43/87

mysqldプロセスが停止していた場合停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能
これらの設定を採用していた場合、「落ち方によってはデータに不整合が発生している」 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップからリストアするなり何なりが必要 ‐ 停止した原因を探す 44/87

mysqldの異常終了で一貫性が損なわれる可能性のあるものテーブル編 InnoDB以外のストレージエンジン ‐ InnoDBでも以下の設定の場合おかしくなり得る skip_innodb_doublewrite innodb_flush_log_at_trx_commit <> 1 innodb_support_xa
= 0 sync_binlog <> 1 ‐ 45/87

= 0 sync_binlog <> 1 ‐ 46/87

= 0 sync_binlog <> 1 MySQL 5.6とそれ以前のデフォルト ‐ 47/87

innodb_flush_log_at_trx_commit vs. mysqldクラッシュ症状 = 1 = 0 = 2
mysqldクラッシュ(*1) o x(*2) o OSパニック o x(*2) x(*2) H/W障害 o x(*2) x(*2) (*1) kill -9はここに含まれる (*2) x = 壊れている可能性がある、壊れていない可能性もある、もちろんメディア障害を除く 48/87

mysqldプロセスが停止していた場合停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップ
からリストアするなり何なりが必要マスターとスレーブのデータがズレればレプリケーションエラーの原因にもなるし、特定のサーバーから読み取った時だけ特定のユーザーの記録がない…なんて「後日じゃ思い付くのも難しい」障害の原因になり得る ‐ 停止した原因を探す 49/87

mysqldの異常終了で一貫性が損なわれる可能性のあるものレプリケーションマスター編 sync_binlog <> 1 ‐ 50/87

mysqldの異常終了で一貫性が損なわれる可能性のあるものレプリケーションマスター編 sync_binlog <> 1 MySQL 5.6とそれ以前のデフォルト ‐
51/87

マスターのバイナリログ末尾が欠損すると mysql> SHOW SLAVE STATUS\G .. Last_IO_Errno: 1236 Last_IO_Error: Got
fatal error 1236 from master when reading data from binary log: 'C lient requested master to start replication from impossible position; the first event 'my sql-bin.003583' at 45997491, the last event read from './mysql-bin.003583' at 4, the last byte read from './mysql-bin.003583' at 4.'.. 52/87

mysqldの異常終了で一貫性が損なわれる可能性のあるものレプリケーションスレーブ編 master_info_repository = FILE (*注) ‐ sync_master_info <> 1
(*注) ‐ relay_log_info_repository = FILE ‐ リレーログ - master_info - relay_log_info - ストレージエンジン間の整合性 (*注) ‐ マスターで binlog_format = STATEMENT の時のテンポラリーファイル ‐ 53/87

mysqldの異常終了で一貫性が損なわれる可能性のあるものレプリケーションスレーブ編 master_info_repository = FILE (*注) MySQL 5.7とそれ以前のデフォルト
‐ sync_master_info <> 1 (*注) MySQL 8.0.17現在もデフォルト ‐ relay_log_info_repository = FILE MySQL 5.7とそれ以前のデフォルト ‐ リレーログ - master_info - relay_log_info - ストレージエンジン間の整合性 (*注) 設定によらず常に ‐ マスターで binlog_format = STATEMENT の時のテンポラリーファイル MySQL 5.6とそれ以前のデフォルト ‐ 54/87

mysqldの異常終了で一貫性が損なわれる可能性のあるもの (*注) master_info とリレーログの一貫性を期待せず、常に relay_log_info だけを信用して master_info を再設定しリレーログを再受信する
relay_log_recovery というパラメーターで一貫性を担保することができるただし relay_log_info - ストレージエンジン間の整合性は担保しなければならないため、ストレージエンジンがInnoDB であることと relay_log_info_repository = TABLE は必須 ‐ 55/87

リレーログ - master_info - relay_log_info - ストレージエンジン間の整合性が崩れると mysql> SHOW
SLAVE STATUS\G .. Last_SQL_Errno: 1032 Last_SQL_Error: Could not execute Delete_rows event on table test.t; Can't find record i n 't', Error_code: 1032; handler error HA_ERR_KEY_NOT_FOUND; the event's master log mysql -bin.000002, end_log_pos 333 .. 56/87

　一度だけなら大丈夫だと思った自分だけは大丈夫だと思っていた 57/87

みんなそういうんですよ（） 58/87

大体の場合、覚悟はできてない「強い心でInnoDB以外のストレージエンジンを撲滅する」 [mysqld] innodb_flush_log_at_trx_commit= 1 ### デフォルトから変更しない sync_binlog= 1 binlog_format=
ROW relay_log_info_repository= TABLE relay_log_recovery 59/87

性能を犠牲にせずに現実的にバランスの良いプラクティス 60/87

「クラッシュしたら必ず毎回フルバックアップや現存するスレーブからデータをコピーし直す」 61/87

閑話休題 mysqldが停止していた原因の調査はちょっと置いておいて 62/87

mysqldが停止していないけれどローカルホストからも接続できないような場合 ps auxwww | grep mysqld で出力はあるけど接続できない mysqld_safe と見間違えないように…
‐ プロセスの起動時刻が異様に最近= プロセスが再起動を繰り返しているパターンも ‐ 接続はできたけどなんかすぐ切断されるタイムアウトが非常に短く設定されていて、クエリーの間隔がサーバー側タイムアウトに引っかかっている ‐ 非常に短い間隔でmysqldがダウンしている ‐ 63/87

mysqld_safe is NOT mysqld $ ps auxww | grep mysqld
yoku0825 2997 0.0 0.0 113316 0 ? S Sep19 0:00 /bin/sh /usr/mysql/8.0.1 7/bin/mysqld_safe --server-id=1080 --basedir=/usr/mysql/8.0.17 --socket=/usr/mysql/8.0.17 /data/mysql.sock --port=64080 --pid-file=/usr/mysql/8.0.17/data/mysql.pid --datadir=/usr/ mysql/8.0.17/data yoku0825 3652 22.5 16.7 1790848 169524 ? Sl Sep19 1673:44 /usr/mysql/8.0.17/bin/m ysqld --basedir=/usr/mysql/8.0.17 --datadir=/usr/mysql/8.0.17/data --plugin-dir=/usr/mysq l/8.0.17/lib/plugin --server-id=1080 --log-error=error.log --pid-file=/usr/mysql/8.0.17/d ata/mysql.pid --socket=/usr/mysql/8.0.17/data/mysql.sock --port=64080 yoku0825 3881 0.0 0.0 112716 964 pts/1 S+ 19:28 0:00 grep --color=auto mysql 64/87

mysqld_safe is NOT mysqld mysqld_safe は中でmysqldを呼ぶシェルスクリプト環境変数の面倒とかulimitの面倒とかumaskの面倒とか見てくれたりする ‐ mysqld が落ちると
mysqld_safe がそれを検知して起動しなおす = mysqld プロセスは何度でも蘇るさ！データの破損で mysqld が異常終了 ‐ mysqld_safe ＜ザオリク！ ‐ データの破損で mysqld が異常終了 ‐ mysqld_safe ＜ザオリク！ ‐ データの破損で略 ‐ 65/87

mysqld_safeの止め方 mysqld が正常終了してももちろん止まる mysqld を正常終了できない時には kill して止めるしかないんだけど、 mysqld_safe は kill
-15 や kill -1 を無視するので注意 ‐ trap '' 1 2 3 15 # we shouldn't let anyone kill us trap '' 13 # not even SIGPIPE https://github.com/mysql/mysql-server/blob/mysql-8.0.17/scripts/ mysqld_safe.sh#L36-L37 66/87

mysqldが細かく再起動を繰り返している場合 mysqld_safe から起動されているのであれば mysqld_safe をkillしたところ、 systemd から起動されているのであれば systemctl stop mysqld
したところの次のクラッシュでそれ以上再起動しなくなる mysqld_safe そのものはDBMS機能を提供しないので好きなだけ kill -9 で止められるし、肝心の mysqld は既にクラッシュを繰り返してるんだし…という状態 ‐ もうこのサーバーのdatadirはアテにならない（したくない）ので、基本的には「生きているスレーブ(場合によってはマスター)からデータをコピーしてくる」または「最近のフルバックアップとバイナリーログから最新のデータを復元」えっ？スレーブもないしバックアップも取ってない？ ‐ 67/87

ちなみにmysqldが落ちっぱなしだった時はここから「落ちっぱなしだったmysqld」は「落ちたけど再起動されなかったmysqld」といっしょ mysqld_safe なり systemd にぶら下がっていた場合は「何故再起動しなかった」というのは調べる必要があるかも知れないけれども ‐ 68/87

mysqldが細かく再起動を繰り返している場合最低限エラーログ ( /var/log/mysqld.log, /var/lib/mysql/hostname.err あたり) は保全するべき真面目にコアファイルを解析するのでなければデータディレクトリーの保全は要らない気もする my.cnf
に core-file を指定していた場合、コアファイルはデータディレクトリーに吐こうとする解析する気もなく「ないよりはあった方が…」みたいなノリでコアファイルを吐かせるならディスクの空き容量に注意を… abrtd が悪さをしてちょっかいをかけて /var/spool/abrt に吐き出したり、あるいは勝手にコアファイルを消されることもある ‐ 69/87

mysqldが細かく再起動を繰り返している場合スレーブの場合はリレーログ、バイナリーログあたりを保全しておくと、（更新が問題だった場合の）再現が多少容易にとはいえ、「条件さえ揃えば同じクエリーで必ず落ちる」のであれば、他のスレーブもきっといっぱい落ちてるから阿鼻叫喚になって既に原因に気が付いている気もする ‐ クラッシュしている時点で relay_log_info_repository= FILE の
relay_log.info はあてにならないし、 relay_log_info_repository= TABLE の場合 mysql/slave_relay_log_info.ibd を人間が読むのはつらいと思う log_slave_updates が設定されていれば、「バイナリーログにはSQLが実行された後にのみ記録される」ことを利用してリレーログと差分を取るのが確実な気がする ‐ 70/87

雑なエラーログの読み取り方(全景) 190618 2:06:02 - mysqld got signal 11 ; This
could be because you hit a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware. We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. key_buffer_size=8388608 read_buffer_size=2097152 max_used_connections=11 max_threads=500 thread_count=10 connection_count=10 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5133883 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x72b8550 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 0x7f3f608e6e68 thread_stack 0x30000 /tools/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x798989] /tools/mysql/bin/mysqld(handle_segfault+0x380)[0x4fde40] /lib64/libpthread.so.0[0x3ca3a0f710] /tools/mysql/bin/mysqld(hp_movelink+0xb)[0x918a5b] /tools/mysql/bin/mysqld(hp_write_key+0x22e)[0x91ba0e] /tools/mysql/bin/mysqld(heap_write+0x9b)[0x91bdcb] /tools/mysql/bin/mysqld(_ZN7ha_heap9write_rowEPh+0x43)[0x917d13] /tools/mysql/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x5c)[0x66db2c] /tools/mysql/bin/mysqld[0x5a41e4] /tools/mysql/bin/mysqld[0x59283b] /tools/mysql/bin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x86)[0x597ec6] /tools/mysql/bin/mysqld[0x59d6dd] /tools/mysql/bin/mysqld(_ZN4JOIN4execEv+0x4ef)[0x5b139f] /tools/mysql/bin/mysqld(_ZN18st_select_lex_unit4execEv+0x1f1)[0x5deea1] /tools/mysql/bin/mysqld(_Z21mysql_derived_fillingP3THDP3LEXP10TABLE_LIST+0x168)[0x559b88] /tools/mysql/bin/mysqld(_Z20mysql_handle_derivedP3LEXPFbP3THDS0_P10TABLE_LISTE+0x69)[0x559989] /tools/mysql/bin/mysqld(_Z20open_and_lock_tablesP3THDP10TABLE_LISTbjP19Prelocking_strategy+0x125)[0x541955] /tools/mysql/bin/mysqld[0x5715c5] /tools/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x226a)[0x576c4a] /tools/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x15a)[0x5790ba] /tools/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1321)[0x57ac31] /tools/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x167)[0x60f0b7] /tools/mysql/bin/mysqld(handle_one_connection+0x54)[0x60f124] /lib64/libpthread.so.0[0x3ca3a079d1] /lib64/libc.so.6(clone+0x6d)[0x3ca32e88fd] Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (0x7f3f20004c00): SELECT dst_ip, SUM(total_stream) AS total_stream, SUM(up_stream) AS up_stream, SUM(down_stream) AS down_stream FROM ( SELECT dst_ip, SUM(oct_upstream + oct_downstream) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS down_stream FROM t_monitor_user_app_if_zone_critical_60min_0 _1560556800 WHERE timestamp >= 1560708343 AND timestamp <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION ALL SELECT dst_ip, SUM(oct_upstream + oct_downstream) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS down_stream FROM t_monitor_user_app_if_zone_critical_60min_0_1560643200 WHERE timestamp >= 1560708343 AND timestamp <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION ALL SELECT dst_ip, SUM(oct_upstream + oct_downstream) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS down_stream FROM t_monitor_user_app_if_zone_critical_60min_0_1560729600 WHERE timestamp >= 1560708343 AND timestam p <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION AL Connection ID (thread ID): 350 Status: NOT_KILLED https://bugs.mysql.com/bug.php?id=95932 71/87

雑なエラーログの読み取り方(1) スタックトレースからなんとなくシンボルの名前で察する .. stack_bottom = 0x7f3f608e6e68 thread_stack 0x30000 /tools/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x798989] /tools/mysql/bin/mysqld(handle_segfault+0x380)[0x4fde40]
/lib64/libpthread.so.0[0x3ca3a0f710] /tools/mysql/bin/mysqld(hp_movelink+0xb)[0x918a5b] /tools/mysql/bin/mysqld(hp_write_key+0x22e)[0x91ba0e] /tools/mysql/bin/mysqld(heap_write+0x9b)[0x91bdcb] /tools/mysql/bin/mysqld(_ZN7ha_heap9write_rowEPh+0x43)[0x917d13] /tools/mysql/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x5c)[0x66db2c] /tools/mysql/bin/mysqld[0x5a41e4] /tools/mysql/bin/mysqld[0x59283b] /tools/mysql/bin/mysqld(_Z10sub_selectP4JOINP13st_join_tableb+0x86)[0x597ec6] /tools/mysql/bin/mysqld[0x59d6dd] /tools/mysql/bin/mysqld(_ZN4JOIN4execEv+0x4ef)[0x5b139f] /tools/mysql/bin/mysqld(_ZN18st_select_lex_unit4execEv+0x1f1)[0x5deea1] /tools/mysql/bin/mysqld(_Z21mysql_derived_fillingP3THDP3LEXP10TABLE_LIST+0x168)[0x559b88] /tools/mysql/bin/mysqld(_Z20mysql_handle_derivedP3LEXPFbP3THDS0_P10TABLE_LISTE+0x69)[0x559989] /tools/mysql/bin/mysqld(_Z20open_and_lock_tablesP3THDP10TABLE_LISTbjP19Prelocking_strategy+0x125)[0x541955] /tools/mysql/bin/mysqld[0x5715c5] /tools/mysql/bin/mysqld(_Z21mysql_execute_commandP3THD+0x226a)[0x576c4a] /tools/mysql/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x15a)[0x5790ba] /tools/mysql/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1321)[0x57ac31] /tools/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x167)[0x60f0b7] /tools/mysql/bin/mysqld(handle_one_connection+0x54)[0x60f124] /lib64/libpthread.so.0[0x3ca3a079d1] /lib64/libc.so.6(clone+0x6d)[0x3ca32e88fd] .. 72/87

雑なエラーログの読み取り方(2) クエリーが直接の原因の場合、当該のクエリーがここに現れることも（現れないことも）あるここに表示されていない, 表示が切り詰められているけど全部知りたい場合はコアファイル解析 ‐ Trying to get some
variables. Some pointers may be invalid and cause the dump to abort. Query (0x7f3f20004c00): SELECT dst_ip, SUM(total_stream) AS total_stream, SUM(up_stream) AS up_s tream, SUM(down_stream) AS down_stream FROM ( SELECT dst_ip, SUM(oct_upstream + oct_downstream ) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS down_stream FROM t_mon itor_user_app_if_zone_critical_60min_0_1560556800 WHERE timestamp >= 1560708343 AND timestamp <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION ALL SELECT dst_ip, SUM(oct_upstream + oct _downstream) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS down_stream FROM t_monitor_user_app_if_zone_critical_60min_0_1560643200 WHERE timestamp >= 1560708343 AND ti mestamp <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION ALL SELECT dst_ip, SUM(oct_ups tream + oct_downstream) AS total_stream, SUM(oct_upstream) AS up_stream, SUM(oct_downstream) AS d own_stream FROM t_monitor_user_app_if_zone_critical_60min_0_1560729600 WHERE timestamp >= 156070 8343 AND timestamp <= 1560794743 AND src_user = 0 GROUP BY dst_ip UNION AL Connection ID (thread ID): 350 Status: NOT_KILLED 73/87

雑なエラーログの読み取り方(3) これは単なる「ハードコードされた決まり文句」なのであまり真に受けない計算式が今更MyISAMなのも古いままで更新されていない以外に深い意味はない（はず） ‐ This could be because you hit
a bug. It is also possible that this binary or one of the libraries it was linked against is corrupt, improperly built, or misconfigured. This error can also be caused by malfunctioning hardware. We will try our best to scrape up some info that will hopefully help diagnose the problem, but since we have already crashed, something is definitely wrong and this may fail. key_buffer_size=8388608 read_buffer_size=2097152 max_used_connections=11 max_threads=500 thread_count=10 connection_count=10 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 5133883 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. 74/87

雑なエラーログの読み取り方(4) そもそもエラーログの末尾（再起動しちゃっているならクラッシュリカバリーの手前あたり）に↑っぽい出力が一切ない場合くだんのログは「 mysqld がSIGSEGV, SIGABRT, SIGILLあたりのシグナルをトラップした」時に出力されるので、 ‐
「トラップされないシグナル」つまりSIGKILLで停止された時はシグナルハンドラーを通らない = エラーログが一切出ない ‐ SIGKILLを叩くものといえばテンパったDBAかOOM Killerくらいだと思うという訳で「エラーログが出ていない」 = 「 /var/log/messages あたりにOOM Killerのログは出ていないか？」と類推できる ‐ エラーログファイルの載っているストレージが壊れている可能性も微レ存には微レ存 ‐ 75/87

mysqldが再起動を繰り返していない場合… 本当に刺さっているのか？リソース不足でログインできないように見えているだけのものを kill -9 で殺してしまうと二次被害が出る ‐ ちゃんと mysqld_safe
なり systemd なりを処理してから停止しないと勝手に起動されてあがががががが ‐ 76/87

mysqldが刺さっているかどうかを調べる方法 mysqldは通信していないかは tcpdump で見られるアプリケーション側から一方的にクエリーを送られてきているだけならOKだけれど、MySQL側からパケットが出て行っているなら実は生きている可能性も ‐ $ sudo tcpdump
-i any port 3306 .. 77/87

mysqldが刺さっているかどうかを調べる方法必ずしも確定できるわけではないけれど top, iotop CPUをぶん回して刺さる場合と、CPUを全く使わずに刺さる2パターンは確かに存在するけれども ‐ ガリガリとストレージに書いている真っ最中なら、まともに処理はできてなくても「何かをデータディレクトリーに書いている最中」である確率は高いので、ストレージへの書き込みが落ち着くまで
kill -9 は待った方が良いかも知れない ‐ $ sudo iotop -p $(pidof mysqld) $ top -p $(pidof mysqld) 78/87

mysqldが刺さっているかどうかを調べる方法ややデンジャーゾーンストレージへの書き込みが継続している場合、「何に書き込んでいるのか」を知りたくなることもあるのでそんな時は pt-ioprofile を使って読み書き対象のファイルを調べることができる strace を使っているので、連打すると mysqld
が死ぬかも知れない ‐ 日々の覚書: percona-toolkit 3.0.12とそれ以前のpt-ioprofileがCentOS 7.xで動かない件 ‐ 79/87

pt-ioprofile $ pt-ioprofile --cell=sizes --profile-pid $(pidof mysqld) --run-time=5 .. total
read pread64 pwrite64 write fdatasync fsync lseek f ilename 117571976835 249992 0 0 249992 0 0 1175714768 51 /data/mysql/mysql-relay.012339 2981888 0 0 2981888 0 0 0 0 / data/mysql/xb_doublewrite 1045504 0 0 1045504 0 0 0 0 / data/mysql/ib_logfile0 405000 0 0 0 405000 0 0 0 / data/mysql/master.info 311296 0 311296 0 0 0 0 0 / data/mysql/some_table.ibd 165654 0 0 0 165654 0 0 0 / data/mysql/mysql-bin.005418 0 0 0 0 0 0 0 0 / data/mysql/undo002 .. 80/87

mysqldが刺さっているかどうかを調べる方法デンジャーゾーンストレージには書いてないけどなんかやたらCPUをぶん回している時は strace も有効 perf top -p $(pidof
mysqld) だと抽象的過ぎてわからないような時に ‐ ただし慣れていないと膨大なノイズに時間ばかり浪費させられるのでよしなに… ‐ strace のオプションはお好みでどうぞ ‐ $ sudo strace -ff -o mysqld_trace -tt -p $(pidof mysqld) .. 81/87

mysqldが刺さっているかどうかを調べる方法デンジャーゾーンみなさまお待ちかねの gdb はデバッグシンボルの有無やMySQLの知識の有無によって得られる情報量が全然違うので常用するかどうかは微妙勿論アタッチしている最中はプロセスの動き止まるので注意 ‐ バックトレースだけ吐き出させておこう…という用途なら↓のコマンドが多少は役に立つか… ‐
$ sudo gdb -p $(pidof mysqld) gdb> thread apply all bt full .. 82/87

mysqldが刺さっているかは調べられないけれど将来の力になるかも知れない方法デンジャーゾーン pt-pmp を使うと gdb の thread apply all
bt をサマリーして表示してくれる中身は gdb と awk でやってるだけなので、やっぱりアタッチ中は動きも止まる ‐ 面白いし勉強になることは確かなんだけど、復旧を急いでいる時にやるかというと微妙（それなら gdb で全部出力させておけばいいんじゃないか感） ‐ 83/87

mysqldが刺さっているかは調べられないけれど将来の力になるかも知れない方法 $ sudo pt-pmp --pid $(pidof mysqld) 291 pthread_cond_wait@@GLIBC_2.3.2,one_thread_per_connection_end,handle_one_connection
57 read,my_real_read,my_net_read,do_command,handle_one_connection,start_thread 26 pthread_cond_wait@@GLIBC_2.3.2,os_event_wait_low,os_aio_simulated_handle,fil_aio_wait,io_handler_thread,start_thread 3 pthread_cond_wait@@GLIBC_2.3.2,os_event_wait_low,srv_purge_worker_thread 1 select,os_thread_sleep,srv_purge_thread 1 select,os_thread_sleep,srv_master_thread 1 select,os_thread_sleep,srv_lock_timeout_and_monitor_thread 1 select,os_thread_sleep,srv_error_monitor_thread 1 select,handle_connections_sockets,main,select 1 read,vio_read_buff,my_real_read,my_net_read,cli_safe_read,handle_slave_io 1 pthread_cond_wait@@GLIBC_2.3.2,os_event_wait_low,sync_array_wait_event,rw_lock_s_lock_spin,buf_page_get_gen,btr_cur_search_to_nth_level,row_search_for_mysql,h a_innodb::index_read,handler::index_read_idx_map,join_read_const,join_read_const_table,make_join_statistics,JOIN::optimize,mysql_select,handle_select,execute_sqlc om_select,mysql_execute_command,mysql_parse,dispatch_command,do_command,handle_one_connection 1 pread64,os_file_pread,os_file_read,fil_io,buf_read_page_low,buf_read_page,buf_page_get_gen,btr_cur_search_to_nth_level,row_search_index_entry,row_upd_step,row _update_for_mysql,ha_innodb::delete_row,handler::ha_delete_row,mysql_delete,mysql_execute_command,mysql_parse,Query_log_event::do_apply_event,apply_event_and_upda te_pos,handle_slave_sql 1 pread64,os_file_pread,os_file_read,fil_io,buf_read_page_low,buf_read_page,buf_page_get_gen,btr_cur_search_to_nth_level,row_search_for_mysql,ha_innodb::index_r ead,handler::index_read_idx_map,join_read_const,join_read_const_table,make_join_statistics,JOIN::optimize,mysql_select,handle_select,execute_sqlcom_select,mysql_e xecute_command,mysql_parse,dispatch_command,do_command,handle_one_connection 1 do_sigwait,sigwait,signal_hand 84/87

mysqldを止める kill -15 で死んでくれることを祈る本当に深いところで刺さってるなら単に無視されるだけ ‐ kill -15 は正常終了シーケンスをトリガーする（ mysqladmin
shutdown も最終的には同じ関数に行きつく）ので、これで終了してくれればめっけもの ‐ シャットダウンシーケンスが始まってくれればその後のクライアントからの要求には ERROR: 1053 Server shutdown in progress. が返るようになるので、上手くすればリソースが枯渇しきっていても正常にシャットダウンが終了する（ただし正常終了シーケンスはgraceful shutdownなので、後続が来なくなったからといってリソースを即解放できずにシャットダウンできないケースはある） ‐ それでもダメなら… kill -9 しかる後、「 mysqld を起動していいのかどうか」の判定に進む ‐ 85/87

まとめリソース枯渇で刺さっているように見えることもあるので切り分ける mysqldが落ちた時に「不整合が起こる可能性のあるもの」「そのまま起動してサービスに戻してはいけないケース」を判断する手で止める時は二次被害に注意 86/87

Any Questions and/or Suggestions? 87/87

Shooting a trouble of MySQL

Shooting a trouble of MySQL

yoku0825 PRO

More Decks by yoku0825

Other Decks in Technology

Featured

Transcript

yoku0825
PRO