2017年8月12日土曜日

数秒おきに ERROR: 2006 MySQL server has gone away でmysqlコマンドラインクライアントの接続が切れる

はじまりは @uessy_akrさん のツイート。






“MySQL Server has gone away” はクライアント側のエラー CR_SERVER_GONE_ERROR で、「クライアントは接続張りっぱなしのつもりなのに次のクエリーを投げたら実はサーバー側から接続を切られていた」時に出るエラー。
よって原因になり得るのは
  • タイムアウトが非常に短く設定されていて、クエリーの間隔がサーバー側タイムアウトに引っかかっている
  • 非常に短い間隔でmysqldがダウンしている
    • サーバープロセスがクラッシュすれば当然、接続していたコネクションは破棄されるから。
      • で、mysqld_safeがすぐにmysqldを再起動するので直後の接続は成功して、またクラッシュするやーつ。
    • 地雷erにはこっちの方が馴染みがある。。
    • SHOW STATUS LIKE 'uptime'ps でmysqldの起動時刻を見たり、エラーログを見たりするのもいい。
  • ネットワークなどに問題があり、しょっちゅう接続が(中間のどこかで)プチプチ切れている
    • 体験したことないけど可能性としては一応
あたり。
で、なんかどうもどうやら






mysqldが毎回クラッシュしている方のケースだったらしい。。
signal 6SIGABRT で、MySQL内部のAssertに引っかかるとこれで落ちる。 ちなみに This could be because you hit a bug. は単なる(?)決まり文句で必ず言われるのであんまり関係ない。 体感で一番起きやすいのはInnoDBのページ破損でAssertに引っかかって食らうことが多い印象。
どうやら大正解だったっぽい。




バックアップがある場合はそこから切り戻すのが一番手っ取り早いし、それができない(最新の状態が壊れたところにしかないとか)場合は innodb_force_recovery を駆使して無理矢理データを引っこ抜くしかない。
この手順はここが丁寧(クラッシュしてるわけじゃないからちょっと状況は違うけど、「解決策 - I. InnoDB の修復」が修復方法に当たる)
( ´-`).oO(あれ、他所へのリンクを貼りまくってるだけの記事になってしまった…

2017年7月19日水曜日

GTIDを有効にしているのにレプリケーションのポジションがズレる場合

TL;DR


GTIDを有効にしてレプリケーションを組んでいる( MASTER_AUTO_POSITION=1 )場合、実行済みのトランザクションのGTIDは gtid_executed に記録される。
そしてI/Oスレッドは 自分のgtid_executedに含まれていない イベントがあれば寄越せ、というように接続時にマスターに要求するし、仮に自分のgtid_executedに含まれているイベントが寄越されてもSQLスレッドが同じGTIDのイベントの二重適用を防ぐ。
これでレプリケーションのポジションはズレない。ズレるはずがない。
gtid_executedが間違っていなければ
じゃあどこでgtid_executedが間違うのか。
  1. gtid_executedはそもそもサーバー変数で、オンメモリーだ。取り敢えずのところ、mysqldが停止しなければgtid_executedは間違わない(はず。間違うならそれはバグだ)
  2. mysqldが停止した場合、サーバー変数のgtid_executedは当然値が失われる。その場合、バイナリーログ(openしてれば)とmysql.gtid_executedから復元する
  3. mysql.gtid_executedはバイナリーログをopenしている場合はバイナリーログのスイッチ時とmysqldのシャットダウン時、openしていない場合はコミットの都度書き込む。マスターは確実にバイナリーログをopenしているので前者の動きになる
  4. ところで、ここに稼働中のマスターサーバーから取ったXtraBackupがあるじゃろ?
  5. トランザクションで保護するからmysql.gtid_executedテーブルはXtraBackup開始時の値が保管されるじゃろ?
  6. XtraBackupはバイナリーログは取らないじゃろ? (あればbinlogに記録されている分からgtid_executedをリカバってくれる)
  7. リストアして CHANGER MASTER TO .. MASTER_AUTO_POSITION= 1 するとサクッとズレる
  8. _| ̄|○
リストアしてから CHANGE MASTER TO .. の前に、 RESET MASTER で gtid_executedの中身を吹っ飛ばし、 SET GLOBAL gtid_purged = '..' で設定するのが正しいと思う。
MySQL 5.7.18とそれ以前のmysqldumpでも同じことが起きる( --all-database でmysql.gtid_executedをダンプしてしまう)し、事実 去年隣にいた人 はmysqldumpで踏んでた。これは最近リリースされたMySQL 5.7.19のmysqldumpでは直っているそうだけれども。
まあ何にせよ注意。。

MySQL 8.0.2以降ではundoテーブルスペースファイルを勝手に拡張してくれるみたい

MySQL 5.7で InnoDB UNDO Log Truncation が追加されたものの、 innodb_undo_tablespacesmysqld --initialize の時に既に指定されていないといけなくて、一度ibdata1が初期化されてしまうと二度と変更できないという制約がありました。
こんなログが出て起動に失敗したりとか失敗したりとか失敗したりとか
2017-07-19T16:00:43.739980+09:00 0 [ERROR] InnoDB: Expected to open 2 undo tablespaces but was able to find only 0 undo tablespaces. Set the innodb_undo_tablespaces parameter to the correct value and retry. Suggested value is 0
ところで、 MySQL 8.0.2からinnodb_undo_tablespacesはデフォルトで2 になるんですが、MySQL 5.7とそれ以前でinnodb_undo_tablespaces=0で初期化したdatadirをアップグレードしようとすると起動しなくなるとか

( ゚д゚) 初心者殺しの罠の気配がする…!

と思ったらなんだか 初期化した後でinnodb_undo_tablespacesが変わってるとUNDOスペースファイルを勝手に再生成してくれる という、とっても親切設計に変わっていたのでした。 5.6とそれ以降だとInnoDBログファイルを自動で再作成してくれるのとよく似たログ。
2017-07-19T07:07:49.402158Z 1 [Note] InnoDB: Expected to open 2 undo tablespaces but found none. Will create 2 new undo tables
paces.
2017-07-19T07:07:49.402171Z 1 [Note] InnoDB: Opened 0 existing undo tablespaces.
2017-07-19T07:07:49.404282Z 1 [Note] InnoDB: Creating UNDO Tablespace ./undo_001
2017-07-19T07:07:49.404306Z 1 [Note] InnoDB: Setting file ./undo_001 size to 10 MB
2017-07-19T07:07:49.404314Z 1 [Note] InnoDB: Physically writing the file full
2017-07-19T07:07:49.427852Z 1 [Note] InnoDB: Creating UNDO Tablespace ./undo_002
2017-07-19T07:07:49.427874Z 1 [Note] InnoDB: Setting file ./undo_002 size to 10 MB
2017-07-19T07:07:49.427879Z 1 [Note] InnoDB: Physically writing the file full
2017-07-19T07:07:49.446756Z 1 [Note] InnoDB: Created 2 undo tablespaces.
2017-07-19T07:07:49.476868Z 1 [Note] InnoDB: Creating shared tablespace for temporary tables
2017-07-19T07:07:49.476924Z 1 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please w
ait ...
2017-07-19T07:07:49.496170Z 1 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2017-07-19T07:07:49.503862Z 1 [Note] InnoDB: Created 128 and tracked 128 new rollback segment(s) in the temporary tablespace.
128 are now active.
2017-07-19T07:07:49.527640Z 1 [Note] InnoDB: Created 128 and tracked 128 new rollback segment(s) in undo tablespace number 1.
128 are now active.
2017-07-19T07:07:49.551586Z 1 [Note] InnoDB: Created 128 and tracked 128 new rollback segment(s) in undo tablespace number 2.
128 are now active.
しかもなんか innodb_undo_log_truncate もデフォルトでONになったみたい。
これはトランザクションの粒度が細かいところだと(少なくとも5.7.5で俺が試した時は)つらそうだったので、ちゃんとベンチマーク取った方がいいかなー。
俺が楽になるとても良い機能追加だ! ビバ!

2017年7月18日火曜日

吉祥寺.pm 11でMySQLのステータスモニタリングについて話をしてきた

「夏の吉祥寺、夏のpm」ってことで行ってきました。
思い起こせば一昨年の YAPC::Asia Tokyo 2015 2日目のLT 、俺のLTの次が magnoliak さんで、「おー吉祥寺かー、いいなーもう少し西側に住んでれば行きたいなー」とかそんなことを考えていました。
(このことをおぼえていて下さったそうで、懇親会でそんな話をできたりしました! ビバYAPC)
それから2年、多摩地域の住人となった今こそ、吉祥寺.pmに参加するのだ!!
というわけで話してきたのは、最近(楽しい方面で)ハマっているステータスモニタリングについてでした。 SQLで引けるからPerlでもPHPでもRubyでもPythonでもGoでもCでもなんでも好きなもので引けばいいんですよ、案外簡単なものです、という話。
あと そーだいさん と久々にキャッキャウフフしてきました。 なお我々、そーだいさんが東京に来てから初めて会ったようです。
今回は事前のリポジトリーの内容がちゃんと整理されていたので(?)、二人でグダグダ言い合うスタイルではなくそーだいさんがテンポよく進めてくれるスタイル。 PostgreSQLのモニタリング周り試してみたいなーと思いつつ、 肝心のモニタリングするPostgreSQLがない あたりどうしようもないなあ。

俺は Chiba.pm生まれ MyNA会とCasual育ち なので、.pmにはやっぱり思い入れがあったりします。
次はおじさんとして出張る組じゃなくて、 若い人 の初セッションとか聞きに行きたいですね :)
俺も kazeburo さんと仕事したいけど、 lhfukamachi がいるのでまだまだ今の会社にいます :)

割と安全にpt-online-schema-changeとかpt-table-checksumを取るための簡単なやり方

TL;DR


想定しているトポロジーはこんな感じ。
  • マスター/スレーブ構成(そもそもスレーブいなければcheck_slave_lagもへったくれもない)
  • pt-osc, pt-tcsなどはマスターサーバーで実行する
check_slave_lag用にユーザーを作る(図の実線部分を担当するためのアカウント) 短期間でDROPするのが前提で、色々面倒なのでスーパーユーザーで行く。FILE権限くらいは確実に要らないからREVOKEしとくか。。
接続元ホストはマスターの外側のIPアドレス。
mysql> CREATE USER pt_osc@xxx.xxx.xxx.xxx IDENTIFIED BY 'yyyyyyyy';
mysql> GRANT ALL ON *.* TO pt_osc@xxx.xxx.xxx.xxx;
mysql> REVOKE FILE ON *.* FROM pt_osc@xxx.xxx.xxx.xxx;
このユーザーはレプリケーションを通じて全てのスレーブに作られるので、一発叩くとマスター上のpt-oscとかが直接アクセスできるようになる。
次はcheck_slave_lagを効かせる スレーブのDSNを指定するためのテーブル を作る。 DSNを直接コマンドラインオプションで指定ではなく、コマンドラインオプションで スレーブのDSNを指定するためのテーブル をDSN指定するのが面倒くさい。 (See also, 日々の覚書: pt-online-schema-change(と、pt-table-checksumとかもろもろ)の—recursion-methodについて
mysql> CREATE TABLE mysql.pt_osc (id int, dsn varchar(255));
mysql> INSERT INTO mysql.pt_osc VALUES (1, 'h=aaa.bbb.ccc.ddd,P=3306');
mysql> INSERT INTO mysql.pt_osc VALUES (1, 'h=eee.fff.ggg.hhh,P=3317');
..
idカラムはカブっても特に問題ないようだ。
↑で作ったユーザーがそのまま全サーバーにいるので、テーブルの中に格納するDSNはホストとポートだけでいいはず。 ここで指定しなかったからといってpt-oscやpt-tcsが流れないわけではないので大丈夫(飽くまでcheck_slave_lagを効かせるかどうか)
敢えてcheck_slave_lagを効かせたくないサーバーがあればINSERTしなければOK。 mysqlスキーマに作っちゃってるけど丁寧にやるならそれ用のスキーマを作った方がいいかも知れない。
テーブルを用意したらpt-oscを流す(progressは趣味) この時のマスターの接続先はソケット接続や127.0.0.1への接続でなく、外側のIPアドレスを指定して、作成したユーザーで接続する。
$ pt-online-schema-change --execute --alter "MODIFY col1 varchar(100) COLLATE utf8_bin NOT NULL" D=d1,t=t1,u=pt_osc,p=yyyyyyyy,h=xxx.xxx.xxx.xxx,P=3306 --recursion-method="dsn=D=mysql,t=pt_osc" --progress=time,5
Found 2 slaves:
マスターのホスト名 -> aaa.bbb.ccc.ddd:3306
マスターのホスト名 -> eee.fff.ggg.hhh:3317
Will check slave lag on:
マスターのホスト名 -> aaa.bbb.ccc.ddd:3306
マスターのホスト名 -> eee.fff.ggg.hhh:3317
..
Found .. slaves:, Will check slave lag on: に指定したものが表示されてればチェックされてる。接続エラーが出てないかどうかだけは注意して見る。
流れ終わったらお掃除しておしまい。
mysql> DROP TABLE mysql.pt_osc;
mysql> DROP USER pt_osc@xxx.xxx.xxx.xxx;
recursion-method=hostsやprocesslistで足りるならそっちを使った方が楽だけど、dsnを使いたい時はこう決め打つと楽だよってことで。

2017年7月12日水曜日

mysqld_safeに "--ledir option can only be used as command line option" と言われたら

TL;DR

  • my.cnfに書いてある ledir の行を消す
  • 今までmy.cnfに書いてあった ledirmysqld_safe にコマンドラインオプションとして渡す
    • ex. mysqld_safe --defaults-file=/data/mysql/my.cnf --ledir=/usr/local/mysql/bin

パッケージもの以外のMySQLで、 mysqld_safe を起動した時に↓のように言われることがある。
mysqld_safe --ledir option can only be used as command line option, found in config file
読んでそのまま、 ledir はコマンドラインオプション( mysqld_safe --ledir=.. の形式)で渡さなければいけないのに、コンフィグファイルから ledir の項目が見つかった、という意味。
MySQL 5.5.55とそれ以降、MySQL 5.6.36とそれ以降、MySQL 5.7.17とそれ以降がこのエラーを吐く。
対応するコミットはこちら。
CVE-2016-6662に関連する何かかと思ったら何の関係もなさそうな時期だった。

2017年6月28日水曜日

MySQLのauto_incrementは実質ULLONG_MAX - 2で打ち止まるはなし

TL;DR


とある事情があってInnoDBのAUTO_INCREMENT関連のコードを読んでいた時に、innobase_next_autoincの中でこんなコードになっていることに気が付いた。
 2497         if (block >= max_value
 2498             || offset > max_value
 2499             || current >= max_value
 2500             || max_value - offset <= offset) {
 2501
 2502                 next_value = max_value;
 2503         } else {
いわゆるフツーのオートインクリメント処理の前段に入るチェックで、現在のauto_incrementの値にauto_increment_incrementの値を足してもデータ型の限界を超えないかとかそんなチェックをしているんだけれど、どうやら 足した結果データ型の限界を超える場合はデータ型の限界値を返す らしい。
データ型の最大値が常に返るから、ぶち抜いた時のエラーは ERROR 1062 (23000): Duplicate entry '..' for key 'PRIMARY' になるのか。ふむふむ。
しかし流れで読んでいたhandler::update_auto_incrementの中にちょっと気になる記述を見つけた。
3589       if (nr == ULLONG_MAX)
3590         DBUG_RETURN(HA_ERR_AUTOINC_READ_FAILED);  // Mark failure
はて。
  • 「払い出されたauto_incrementの値がULLONG_MAXだったらHA_ERR_AUTOINC_READ_FAILED」
ということは
  • 「現在のauto_increment値がUULONG_MAX - 1の時にauto_incrementの払い出しをしようとすると、UULONG_MAXが払い出されるから(データ型上はまだ入るけど)エラー」
なのか?
mysql57 13> INSERT INTO t1 VALUES (18446744073709551614, 'BIGINT MAX - 1');
Query OK, 1 row affected (0.00 sec)

mysql57 13> SELECT * FROM t1;
+----------------------+----------------+
| num                  | val            |
+----------------------+----------------+
| 18446744073709551614 | BIGINT MAX - 1 |
+----------------------+----------------+
1 row in set (0.00 sec)

mysql57 13> INSERT INTO t1 VALUES (NULL, 'NEXT');
ERROR 1467 (HY000): Failed to read auto-increment value from storage engine

mysql57 13> SELECT * FROM t1;
+----------------------+----------------+
| num                  | val            |
+----------------------+----------------+
| 18446744073709551614 | BIGINT MAX - 1 |
+----------------------+----------------+
1 row in set (0.00 sec)
おおおホントだ入らない。 しかしデータ型としてはまだもう1つ行けるので、直接値を指定すれば入る。
mysql57 13> INSERT INTO t1 VALUES (18446744073709551615, 'BIGINT MAX');
Query OK, 1 row affected (0.01 sec)

mysql57 13> SELECT * FROM t1;
+----------------------+----------------+
| num                  | val            |
+----------------------+----------------+
| 18446744073709551614 | BIGINT MAX - 1 |
| 18446744073709551615 | BIGINT MAX     |
+----------------------+----------------+
2 rows in set (0.00 sec)
しかもこの時も、auto_incrementの値がBIGINT UNSIGNEDの最大値の18446744073709551615以上になるから18446744073709551615が返ってDuplicate Entryエラーになる前に、払い出しそのものに失敗した扱いでER_AUTOINC_READ_FAILEDが返るのね。。
18446744073709551614と18446744073709551615の差が生死を分けることはないと思いますが、みなさまご注意ください。