Shooting a trouble of MySQL

2019/09/26 db tech showcase Tokyo 2019 B8
https://www.db-tech-showcase.com/dbts/tokyo

Fixed wrong information in page 48 at 2019/10/02.

Transcript

1. Shooting a trouble of MySQL 今日も今日とてマイエスキューエる 2019/09/26 yoku0825 db tech showcase Tokyo 2019
2. ＼こんにちは／ yoku0825＠とある企業のDBA オラクれない ‐ ポスグれない ‐ マイエスキューエる ‐ 生息域 Twitter: @yoku0825 ‐ Blog: 日々の覚書 ‐ 日本MySQLユーザ会 ‐ MySQL Casual ‐ 1/87
3. Shooting a trouble of MySQL MySQLに 「つながらない」 「どう」 「つながらない」のかを切り分ける 2/87
4. SSHから DBサーバーに対する接続性を確認する OSのハングアップでは ping や TCP SYN , SNMP などは 応答されてしまう ケースがあるので、 その後の操作も兼ねて ssh が一番確実 ‐ DBサーバーでシェルが使えない場合は成功したつもりになって飛ばすしかない ‐ $ ssh db-server .. 3/87
5. DBサーバーにSSHログインできた？ できない ネットワークに異常はない？ サーバーをハードウェア的に調査？ いずれにせよ一旦この資料のスコー プの外に出ます（ハコが復旧したら戻ってきてください） できる 切り分けは続く 4/87
6. HA用のミドルウェアをなにがしか使っている場合 MHA for MySQL, mikasafabric for MySQL, MMM, Orchestrator, .. この時点で そのサーバーの電源を落とす 方が二次被害が起こるリスクを減らせる 死にかけのサーバーがフェイルオーバープロセスを噛んじゃってフェイルオーバーが進まない ‐ 折角マスターのフェイルオーバーに成功したのに、旧マスターがゾンビのように生き続けてい て一部サーバーはそちらに書き込んでしまった ‐ ロードバランサーの分散に入ったり外れたりを繰り返してサービスが不安定になった ‐ 5/87
7. トラブル箇所の切り分け ローカルホストの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
8. ローカルホストのMySQL接続はできた？ できない 次ページからの解説へ できる 切り分けは続く 7/87
9. ローカルホストの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
10. エラーコードに注目する 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
11. エラーコードに注目する 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
12. エラーコードに注目する 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
13. エラーコードに注目する ERROR 2003 (HY000): Can't connect to MySQL server on '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
14. エラーコードに注目する ERROR 2003 (HY000): Can't connect to MySQL server on '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
15. エラーコードに注目する 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
16. エラーコードに注目する ERROR 1040 (08004): Too many connections MySQLエラーコード: 1040 エラーメッセージ: Too many connections OSエラーコード: なし 15/87
17. エラーコードに注目する ERROR 3032 (HY000): The server is currently in offline mode MySQLエラーコード: 3032 エラーメッセージ: The server is currently in offline mode OSエラーコード: なし 16/87
18. エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」 それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサ イドエラー」 17/87
19. エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」 クライアントサイドエラーは基本的に「接続できなかった」「接続できそうだけどできなかっ た」「接続できたけどダメだった」くらいの情報しかない ‐ クライアントサイドエラーとOSエラーコードはセットで表示されることが多い ‐ それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサ イドエラー」 18/87
20. エラーメッセージで覚えておくべき2つのこと MySQLエラーコードの2000番台は「クライアントサイドエラー」 それ以外（1000番台、3000番台、8.0では10000番オーバーも）は「サーバーサ イドエラー」 MySQLプロトコルにおいて サーバーサイドエラーはERRパケットを通じてサーバーから明示的 に送信される ‐ サーバーサイドエラーが返ってきているなら、mysqldそのものの障害ではない可能性が高い ‐ 19/87
21. サーバーサイドエラー 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
22. サーバーサイドエラー ERROR 1040 (08004): Too many connections MySQLエラーコード: 1040 エラーメッセージ: Too many connections OSエラーコード: なし 21/87
23. ローカルホストのMySQL接続はできた…けど 取り敢えず SHOW PROCESSLIST かな FULL はお好みで ‐ mysql> SHOW PROCESSLIST; 22/87
24. SHOW PROCESSLISTから読み解くもの mysql> SHOW PROCESSLIST; .. 4 rows in set (0.00 sec) 取り敢えず一発目はログが流れても構わないので最後の n rows in set を見ましょ う それがほぼ （レプリケーション関連のスレッドやINSERT Delayedスレッド、イベントスケジューラーなどを含むが大体は数が小さいので無視して構わない） 現在の接続中（接続 シーケンス中のクライアントコネクションも含むが、 max_connections とかは接続 シーケンス中のものも含むので問題ないはず）のコネクションの数になる 23/87
25. SHOW PROCESSLISTから読み解くもの mysql> SHOW PROCESSLIST; .. 4 rows in set (0.00 sec) n rows in set を見た時に、 max_connections の値に対して余裕があるか？ ‐ 数回叩いても平常時と比べて非常に高い/低い値をさまよっていないか？ ‐ 24/87
26. SHOW PROCESSLISTから更に読み解くもの スリープしてるコネクションを除外して表示させる mysql> pager grep -v Sleep mysql> SHOW PROCESSLIST; .. 4 rows in set (0.00 sec) 25/87
27. SHOW PROCESSLISTから更に読み解くもの mysql> pager grep -v Sleep mysql> SHOW PROCESSLIST; .. 4 rows in set (0.00 sec) ざっとスリープ以外の出力結果を見た時に、 バックグラウンドスレッド以外で Time が異様に大きいクエリーはないか？ ‐ Info には実行中のクエリーが表示されるが、似たようなクエリーが並んでいないか？ ‐ 26/87
28. SHOW PROCESSLISTから更に読み解くもの | 36 | root | localhost | mysqlslap | Query | 0 | Sending to client | SELECT intcol1, charcol1 FROM t1 | | 37 | root | localhost | mysqlslap | Query | 0 | waiting for handler commit | INSERT INTO t1 VALUES (73673339,'BN3152Gza4GW7atxJKACYwJqDbFynLxqc0kh30YTwgz3FktQ43XTrqJ4PQ25frn7kXh | | 38 | root | localhost | mysqlslap | Query | 0 | executing | SELECT intcol1, charcol1 FROM t1 | | 39 | root | localhost | mysqlslap | Query | 0 | Sending to client | SELECT intcol1, charcol1 FROM t1 | | 40 | root | localhost | mysqlslap | Query | 0 | Sending to client | SELECT intcol1, charcol1 FROM t1 | | 41 | root | localhost | mysqlslap | Query | 0 | Sending to client | SELECT intcol1, charcol1 FROM t1 | | 42 | root | localhost | mysqlslap | Query | 0 | Sending to client | SELECT intcol1, charcol1 FROM t1 | 27/87
29. Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比 較的低い スレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有す るメモリーは案外大きく影響を受けることがある 28/87
30. Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比 較的低い ただしもちろんコア数が少なかったり重いクエリーが 多重 で流されるとCPUを食い尽くすこと も ‐ スレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有す るメモリーは案外大きく影響を受けることがある 29/87
31. Timeが異様に大きいクエリー MySQLは1クエリーをシングルスレッドでさばくのでCPUネックになる可能性は比 較的低い スレッドが分かれているといっても、ストレージのI/O帯域やスレッド間で共有す るメモリーは案外大きく影響を受けることがある テンポラリーテーブルを使うSELECT は書き込みを行うことがよくある ‐ InnoDBバッファプールはスレッド間で共有される ‐ 30/87
32. Infoに似たようなクエリーが並ぶ 特に INSERT, UPDATE, DELETE や SELECT .. FOR UPDATE の排他ロックを取るクエ リー ロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソース をそこそこ食っていて… 31/87
33. Infoに似たようなクエリーが並ぶ 特に INSERT, UPDATE, DELETE や SELECT .. FOR UPDATE の 排他ロック を取るクエ リー ロックの競合自体は「データベースの整合性」を保つために DBMSが備えた機能 ‐ MySQL側にもロック待ちのタイムアウト（主に innodb_lock_wait_timeout, デフォルト50秒） は設定できるが、 タイムアウトするまでの間APサーバーはコネクションを維持したまま待たな くてはいけない ので、APサーバーはその間新たなリクエストを受け止め続けなくてはいけなく なる lock_wait_timeout, innodb_lock_wait_timeout を十分短く設定するか、APサーバー側でもタイムアウトを設定する か APサーバー側でタイムアウトした場合、MySQLのコネクションをちゃんとクローズしてくれるかどうかは実装依存 ‐ ロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソース をそこそこ食っていて… 32/87
34. Infoに似たようなクエリーが並ぶ 特に INSERT, UPDATE, DELETE や SELECT .. FOR UPDATE の排他ロックを取るクエ リー ロックの競合でなくとも、特定のページから呼び出されるクエリーが実はリソース をそこそこ食っていて… 典型的なパターンは「テーブルスキャンあるいは大量レコード」「バッファプールにデータが 乗り切っている」「テンポラリーテーブルを使っている」 ‐ リソースに余裕がある間はそれなりの速度 で応答を返せるものの、一定以上のアクセスが集中 するとサチる ‐ 33/87
35. SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッション を KILL すれば暫定復旧するはず ただの SELECT に見えても実はそれがトランザクションの一部で、 KILL したら大 量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない 限りは無限にクエリーが積もり続ける可能性がある 34/87
36. SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーなら そのセッション を KILL すれば暫定復旧するはず KILL QUERY で停止しても トランザクションはロールバックされるとは限らない （アプリケー ション依存） ‐ KILL で トランザクションごとロールバックしたとしても、再実行はどうする か…？ ‐ ただの SELECT に見えても実はそれがトランザクションの一部で、 KILL したら大 量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない 限りは無限にクエリーが積もり続ける可能性がある 35/87
37. SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッション を KILL すれば暫定復旧するはず 単発の SELECT に見えても実はそれがトランザクションの一部で、 KILL したら大 量ロールバックが走る可能性がある SHOW ENGINE INNODB STATUS TRANSACTIONSセクションの MySQL thread id %d と突き合わせ て、 undo log entries の値を確認する ‐ ロールバックは更新よりも 重い 処理なので、今後の処理の流れが見通せるなら「待った方が結 果的に復旧が速い」ことは十分ある ‐ APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない 限りは無限にクエリーが積もり続ける可能性がある 36/87
38. 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
39. SHOW PROCESSLISTから原因がわかるのなら… 深く考える必要のない単純な参照で明らかに単発のクエリーならそのセッション を KILL すれば暫定復旧するはず ただの SELECT に見えても実はそれがトランザクションの一部で、 KILL したら大 量ロールバックが走って… APサーバーからのトラフィックに依存するならそのページへのアクセスを止めない 限りは 無限にクエリーが積もり続ける可能性が ある ワンライナーでそれっぽいクエリーを KILL し続けながら、AP側への修正がリリースされるの を待ち続ける ‐ 38/87
40. 切り分けは大事 監視の段階で切り分けまでざっくり済ませられるようだと対応速度が上がる ytkit - Yoku-san no ToolKIT に yt-healthcheck として実装・公開 ‐ 長時間実行が続いているクエリーの監視、 コネクション数 / max_connections の 割合の監視、テーブルの AUTOINC の値のパーセンテージの監視… およびそれらの閾値に引っ掛かった時の、 SHOW FULL PROCESSLIST や SHOW ENGINE INNODB STATUS の情報をファイルに出力して保全しておく機能 ‐ 39/87
41. ひとやすみ 40/87
42. 今北産業 mysqldプロセスが生きていてリソースに問題がありそうな場合のトラブルシュー トをなぞってきた 次はmysqldプロセスが生きていない/ハングアップしている場合のトラブルシュー ト ( ´-｀).oO（あっ、2行だ 41/87
43. mysqldプロセスが停止していた場合 停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断 する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップ からリストアするなり何なりが必要 ‐ 停止した原因を探す 42/87
44. mysqldプロセスが停止していた場合 停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか 判 断する MySQLにおける非同期レプリケーションの整合性レベルは 結果整合性 正常停止しなかった場合のマスターとスレーブのデータの整合性は 自分で保証しなければならない ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップ からリストアするなり何なりが必要 ‐ 停止した原因を探す 43/87
45. mysqldプロセスが停止していた場合 停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか 判 断する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「 耐障害性を落として更新性能を上げる 」設定が可能 これらの設定を採用していた場合、「 落ち方によっては データに不整合が発生している」 ‐ マスターにせよスレーブにせよ、データの整合性が担保できないのであればフルバックアップ からリストアするなり何なりが必要 ‐ 停止した原因を探す 44/87
46. mysqldの異常終了で一貫性が損なわれる可能性のあるもの テーブル編 InnoDB以外のストレージエンジン ‐ InnoDBでも以下の設定の場合おかしくなり得る skip_innodb_doublewrite innodb_flush_log_at_trx_commit <> 1 innodb_support_xa = 0 sync_binlog <> 1 ‐ 45/87
47. mysqldの異常終了で一貫性が損なわれる可能性のあるもの テーブル編 InnoDB以外のストレージエンジン ‐ InnoDBでも以下の設定の場合おかしくなり得る skip_innodb_doublewrite innodb_flush_log_at_trx_commit <> 1 innodb_support_xa = 0 sync_binlog <> 1 ‐ 46/87
48. mysqldの異常終了で一貫性が損なわれる可能性のあるもの テーブル編 InnoDB以外のストレージエンジン ‐ InnoDBでも以下の設定の場合おかしくなり得る skip_innodb_doublewrite innodb_flush_log_at_trx_commit <> 1 innodb_support_xa = 0 sync_binlog <> 1 MySQL 5.6とそれ以前のデフォルト ‐ 47/87
49. 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
50. mysqldプロセスが停止していた場合 停止したmysqldを起動しても良いか, あるいはスレーブを昇格させても良いか判断 する MySQLにおける非同期レプリケーションの整合性レベルは結果整合性 ‐ MySQLでは「耐障害性を落として更新性能を上げる」設定が可能 ‐ マスターにせよスレーブにせよ、 データの整合性が担保できないのであればフルバックアップ からリストア するなり何なりが必要 マスターとスレーブのデータがズレればレプリケーションエラーの原因にもなるし、 特定のサーバーから読み取った時だけ特定のユーザーの記録がない…なんて「 後日じゃ思い付くのも難しい 」障害 の原因になり得る ‐ 停止した原因を探す 49/87
51. mysqldの異常終了で一貫性が損なわれる可能性のあるもの レプリケーションマスター編 sync_binlog <> 1 ‐ 50/87
52. mysqldの異常終了で一貫性が損なわれる可能性のあるもの レプリケーション マスター 編 sync_binlog <> 1 MySQL 5.6とそれ以前のデフォルト ‐ 51/87
53. マスターのバイナリログ末尾が欠損すると 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
54. mysqldの異常終了で一貫性が損なわれる可能性のあるもの レプリケーションスレーブ編 master_info_repository = FILE (*注) ‐ sync_master_info <> 1 (*注) ‐ relay_log_info_repository = FILE ‐ リレーログ - master_info - relay_log_info - ストレージエンジン間の整合性 (*注) ‐ マスターで binlog_format = STATEMENT の時のテンポラリーファイル ‐ 53/87
55. 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
56. mysqldの異常終了で一貫性が損なわれる可能性のあるもの (*注) master_info とリレーログの一貫性を期待せず、 常に relay_log_info だけ を信用して master_info を再設定しリレーログを再受信する relay_log_recovery というパラメーターで一貫性を担保することができる ただし relay_log_info - ストレージエンジン間の整合性は担保しなければならないため、 スト レージエンジンがInnoDB であることと relay_log_info_repository = TABLE は必須 ‐ 55/87
57. リレーログ - 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
58. 　 一度だけなら大丈夫だと思った 自分だけは大丈夫だと思っていた 57/87
59. みんなそういう んですよ（） 58/87
60. 大体の場合、覚悟はできてない 「強い心で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
61. 性能を犠牲にせずに 現実的にバランスの 良いプラクティス 60/87
62. 「クラッシュしたら必ず 毎回フルバックアップや 現存するスレーブから データをコピーし直す」 61/87
63. 閑話休題 mysqldが停止していた原因の 調査はちょっと置いておいて 62/87
64. mysqldが停止していないけれどローカルホストからも接続できないような場 合 ps auxwww | grep mysqld で出力はあるけど接続できない mysqld_safe と見間違えないように… ‐ プロセスの起動時刻が異様に最近= プロセスが再起動を繰り返しているパターンも ‐ 接続はできたけどなんかすぐ切断される タイムアウトが非常に短く設定されていて、クエリーの間隔がサーバー側タイムアウトに引っ かかっている ‐ 非常に短い間隔でmysqldがダウンしている ‐ 63/87
65. 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
66. mysqld_safe is NOT mysqld mysqld_safe は中でmysqldを呼ぶシェルスクリプト 環境変数の面倒とかulimitの面倒とかumaskの面倒とか見てくれたりする ‐ mysqld が落ちると mysqld_safe がそれを検知して起動しなおす = mysqld プロセ スは何度でも蘇るさ！ データの破損で mysqld が異常終了 ‐ mysqld_safe ＜ ザオリク！ ‐ データの破損で mysqld が異常終了 ‐ mysqld_safe ＜ ザオリク！ ‐ データの破損で略 ‐ 65/87
67. 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
68. mysqldが細かく再起動を繰り返している場合 mysqld_safe から起動されているのであれば mysqld_safe をkillしたところ、 systemd から起動されているのであれば systemctl stop mysqld したところの次の クラッシュでそれ以上再起動しなくなる mysqld_safe そのものはDBMS機能を提供しないので好きなだけ kill -9 で止められるし、肝 心の mysqld は既にクラッシュを繰り返してるんだし…という状態 ‐ もうこのサーバーのdatadirはアテにならない（したくない）ので、基本的には 「生きているスレーブ(場合によってはマスター)からデータをコピーしてくる」ま たは「最近のフルバックアップとバイナリーログから最新のデータを復元」 えっ？ スレーブもないしバックアップも取ってない？ ‐ 67/87
69. ちなみにmysqldが落ちっぱなしだった時はここから 「落ちっぱなしだったmysqld」は「落ちたけど再起動されなかったmysqld」と いっしょ mysqld_safe なり systemd にぶら下がっていた場合は「何故再起動しなかった」というのは調 べる必要があるかも知れないけれども ‐ 68/87
70. mysqldが細かく再起動を繰り返している場合 最低限エラーログ ( /var/log/mysqld.log, /var/lib/mysql/hostname.err あたり) は保全するべき 真面目にコアファイルを解析するのでなければデータディレクトリーの保全は要らない気もす る my.cnf に core-file を指定していた場合、コアファイルはデータディレクトリーに吐こうとする 解析する気もなく「ないよりはあった方が…」みたいなノリでコアファイルを吐かせるならディスクの空き容量に注 意を… abrtd が 悪さをして ちょっかいをかけて /var/spool/abrt に吐き出したり、あるいは勝手にコアファイルを消され ることもある ‐ 69/87
71. 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
72. 雑なエラーログの読み取り方(全景) 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
73. 雑なエラーログの読み取り方(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
74. 雑なエラーログの読み取り方(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
75. 雑なエラーログの読み取り方(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
76. 雑なエラーログの読み取り方(4) そもそもエラーログの末尾（再起動しちゃっているならクラッシュリカバリーの手 前あたり）に↑っぽい出力が一切ない場合 くだんのログは「 mysqld がSIGSEGV, SIGABRT, SIGILLあたりのシグナルをトラップした」時 に出力されるので、 ‐ 「トラップされないシグナル」つまりSIGKILLで停止された時はシグナルハンドラーを通らな い = エラーログが一切出ない ‐ SIGKILLを叩くものといえばテンパったDBAかOOM Killerくらいだと思う という訳で「エラーログが出ていない」 = 「 /var/log/messages あたりにOOM Killerのログは 出ていないか？」と類推できる ‐ エラーログファイルの載っているストレージが壊れている可能性も微レ存には微レ存 ‐ 75/87
77. mysqldが再起動を繰り返していない場合… 本当に刺さっているのか？ リソース不足でログインできないように見えているだけのものを kill -9 で殺してしまうと二 次被害が出る ‐ ちゃんと mysqld_safe なり systemd なりを処理してから停止しないと勝手に起動されてあがが がががが ‐ 76/87
78. mysqldが刺さっているかどうかを調べる方法 mysqldは通信していないかは tcpdump で見られる アプリケーション側から一方的にクエリーを送られてきているだけならOKだけれど、MySQL側 からパケットが出て行っているなら実は生きている可能性も ‐ $ sudo tcpdump -i any port 3306 .. 77/87
79. mysqldが刺さっているかどうかを調べる方法 必ずしも確定できるわけではないけれど top, iotop CPUをぶん回して刺さる場合と、CPUを全く使わずに刺さる2パターンは確かに存在するけれど も ‐ ガリガリとストレージに書いている真っ最中なら、まともに処理はできてなくても「何かを データディレクトリーに書いている最中」である確率は高いので、ストレージへの書き込みが 落ち着くまで kill -9 は待った方が良いかも知れない ‐ $ sudo iotop -p $(pidof mysqld) $ top -p $(pidof mysqld) 78/87
80. mysqldが刺さっているかどうかを調べる方法 ややデンジャーゾーン ストレージへの書き込みが継続している場合、「何に書き込んでいるのか」を知り たくなることもあるのでそんな時は pt-ioprofile を使って読み書き対象のファイル を調べることができる strace を使っているので、連打すると mysqld が死ぬかも知れない ‐ 日々の覚書: percona-toolkit 3.0.12とそれ以前のpt-ioprofileがCentOS 7.xで動かない件 ‐ 79/87
81. 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
82. mysqldが刺さっているかどうかを調べる方法 デンジャーゾーン ストレージには書いてないけどなんかやたらCPUをぶん回している時は strace も 有効 perf top -p $(pidof mysqld) だと抽象的過ぎてわからないような時に ‐ ただし慣れていないと膨大なノイズに時間ばかり浪費させられるのでよしなに… ‐ strace のオプションはお好みでどうぞ ‐ $ sudo strace -ff -o mysqld_trace -tt -p $(pidof mysqld) .. 81/87
83. mysqldが刺さっているかどうかを調べる方法 デンジャーゾーン みなさまお待ちかねの gdb はデバッグシンボルの有無やMySQLの知識の有無に よって得られる情報量が全然違うので常用するかどうかは微妙 勿論アタッチしている最中はプロセスの動き止まるので注意 ‐ バックトレースだけ吐き出させておこう…という用途なら↓のコマンドが多少は役に立つか… ‐ $ sudo gdb -p $(pidof mysqld) gdb> thread apply all bt full .. 82/87
84. mysqldが刺さっているかは調べられないけれど将来の力になるかも知れない 方法 デンジャーゾーン pt-pmp を使うと gdb の thread apply all bt をサマリーして表示してくれる 中身は gdb と awk でやってるだけなので、やっぱりアタッチ中は動きも止まる ‐ 面白いし勉強になることは確かなんだけど、復旧を急いでいる時にやるかというと微妙（それ なら gdb で全部出力させておけばいいんじゃないか感） ‐ 83/87
85. 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
86. mysqldを止める kill -15 で死んでくれることを祈る 本当に深いところで刺さってるなら単に無視されるだけ ‐ kill -15 は正常終了シーケンスをトリガーする（ mysqladmin shutdown も最終的には同じ関数 に行きつく）ので、これで終了してくれればめっけもの ‐ シャットダウンシーケンスが始まってくれればその後のクライアントからの要求には ERROR: 1053 Server shutdown in progress. が返るようになるので、上手くすればリソースが枯渇し きっていても正常にシャットダウンが終了する（ただし正常終了シーケンスはgraceful shutdownなので、後続が来なくなったからといってリソースを即解放できずにシャットダウン できないケースはある） ‐ それでもダメなら… kill -9 しかる後、「 mysqld を起動していいのかどうか」の判定に進む ‐ 85/87
87. まとめ リソース枯渇で刺さっているように見えることもあるので切り分ける mysqldが落ちた時に「不整合が起こる可能性のあるもの」「そのまま起動して サービスに戻してはいけないケース」を判断する 手で止める時は二次被害に注意 86/87
88. Any Questions and/or Suggestions? 87/87