そーだいなるらくがき帳

そーだいが自由気侭に更新します。

なぜあなたは SHOW ENGINE INNODB STATUS を読まないのか

この記事は、MySQL Casual Advent Calendar 2017の20日目の記事です。

煽り気味のタイトルですがみなさん SHOW ENGINE INNODB STATUS 読んでますか?

わかる。でもMySQLの振る舞いを知る中でSHOW ENGINE INNODB STATUSを読まざる得ない場面はそこそこあります。 どんな時に必要になるのでしょうか? そこでSHOW ENGINE INNODB STATUSにまつわる話を書きます。

SHOW ENGINE INNODB STATUS をまず読みやすくする

まず末尾に \G を付けましょう。 これで3倍読みやすくなります。 次に pager less -S を使いましょう。 これでlessで開いた状態で読めます。

mysql> pager less -S
PAGER set to 'less -S'

mysql> SHOW ENGINE INNODB STATUS\G

さて読む準備は整いました。

SHOW ENGINE INNODB STATUSを読み解く

読み慣れて無い方はまず、 id:myfinder さんのスライドを読みましょう。 SHOW ENGINE INNODB STATUSの勘所が書いてあります。

www.slideshare.net

ほら読める気がしてきた。 けどこのへんの値は実はPMP(Percona Monitoring Plugins)とか使うと可視化してくれます。 みんな大好き @yoku0825 さんもオススメしてます。

thinkit.co.jp

勿論同等以上の事は Mackerel でも出来る(InnoDBの監視は今日の予定なので待っててくれ!!)

soudai.hatenablog.com

soudai.hatenablog.com

しかしそれでも SHOW ENGINE INNODB STATUS を見ないといけない日はあります。 それは細かいロックの挙動を調べるときでしょう。

デッドロックを調べる

ロックの挙動を調べるにはまずInnoDB ロックモニターを有効化する必要があります。

mysql> pager less -S
PAGER set to 'less -S'

mysql> set GLOBAL innodb_status_output_locks=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW ENGINE INNODB STATUS\G

ロックを調べるときはみんな大好き id:kamipo さんも SHOW ENGINE INNODB STATUS を使っています!

blog.kamipo.net

ロックの見方についてはkamipoさんの記事でカバーされているので今回は割愛します。 我々がSHOW ENGINE INNODB STATUSを求める時、それはデッドロックが発生しているときでしょう(だいたい僕はそうです)

手っ取り早くデッドロックを起こします。

-- トランザクション A
mysql> begin;
mysql> INSERT INTO child VALUES (1, 1);
Query OK, 1 row affected (0.00 sec)

--トランザクションB
mysql> begin;
mysql> INSERT INTO  child values (1, 2);
Query OK, 1 row affected (0.00 sec)

-- トランザクション A
mysql> UPDATE parent SET count = count + 1 WHERE id = 1;
-- 待たされます!

-- トランザクション B
mysql> UPDATE parent SET count = count + 2 WHERE id = 1;
ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

いえーい!外部キー制約によるデッドロック!!(よく見る) この場合、SHOW ENGINE INNODB STATUSに LATEST DETECTED DEADLOCK が現れます。

公式ドキュメントからの引用

MySQL :: MySQL 5.6 リファレンスマニュアル :: 14.15.3 InnoDB 標準モニターおよびロックモニターの出力

LATEST DETECTED DEADLOCK このセクションは、最新のデッドロックに関する情報を提供します。デッドロックが発生していない場合は存在しません。その内容には、関連しているトランザクション、各トランザクションが実行しようとしていたステートメント、それぞれが保持しているロックと必要なロック、およびデッドロックを解消するために InnoDBロールバックすることを決定したトランザクションが示されます。このセクションでレポートされるロックモードについては、セクション14.2.3「InnoDB のロックモード」で説明されています。

実際はこんな感じです。

------------------------
LATEST DETECTED DEADLOCK
------------------------
2017-12-19 17:18:44 7f05bcc0d700
*** (1) TRANSACTION:
TRANSACTION 5999052, ACTIVE 19 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 3919, OS thread handle 0x7f05bcbcc700, query id 19851 localhost root updating
UPDATE parent SET count = count + 1 WHERE id = 1
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 20 page no 3 n bits 72 index `PRIMARY` of table `hoge`.`parent` trx id 5999052 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000005b89b2; asc    [  ;;
 2: len 7; hex a1000001550110; asc     U  ;;
 3: len 4; hex 80000000; asc     ;;

*** (2) TRANSACTION:
TRANSACTION 5999053, ACTIVE 10 sec starting index read
mysql tables in use 1, locked 1
5 lock struct(s), heap size 1184, 2 row lock(s), undo log entries 1
MySQL thread id 3886, OS thread handle 0x7f05bcc0d700, query id 19852 localhost root updating
UPDATE parent SET count = count + 2 WHERE id = 1
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 20 page no 3 n bits 72 index `PRIMARY` of table `hoge`.`parent` trx id 5999053 lock mode S locks rec but not gap
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000005b89b2; asc    [  ;;
 2: len 7; hex a1000001550110; asc     U  ;;
 3: len 4; hex 80000000; asc     ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 20 page no 3 n bits 72 index `PRIMARY` of table `hoge`.`parent` trx id 5999053 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 4; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 0000005b89b2; asc    [  ;;
 2: len 7; hex a1000001550110; asc     U  ;;
 3: len 4; hex 80000000; asc     ;;

*** WE ROLL BACK TRANSACTION (2)

TRANSACTION (2)がデッドロックによってロールバックしていることがわかります。 このようにデッドロックを紐解くためには SHOW ENGINE INNODB STATUS が役にたちます。

その他には?

最新の外部キー制約エラーがわかる LATEST FOREIGN KEY ERROR やロックの状態自体やクエリの振る舞いを知るためには TRANSACTION を覗くのが良いでしょう。 しかしSHOW ENGINE INNODB STATUSはその時の状態なので本番で常にSQLが複数回実行されるような場合では1度実行しただけでは全てを知ることが出来ません。 実際には set GLOBAL innodb_status_output=ON; を実行してSHOW ENGINE INNODB STATUSの情報をエラーログに20秒置きに吐いておき、それを見比べながらロックを取り合えっているSQLを調べることになります。 クエリを見比べるときは id:sh2 さんのもう1億回くらい見たであろう下記の記事からロック競合を表示するSQLのViewを作っておきましょう。 僕はさらにこれを5秒に1回ログに保存したりしてました。

MySQL InnoDBにおけるロック競合の解析手順 - SH2の日記

おっと、ロックについてちょっと熱くなってしまいました。 ロックは主題ではないので話がずれましたがあとは id:ichirin2501 詳しい人に聞いてください!

より深く知るためには?

ちなみに PMP for Cacti については下の本にめっちゃ詳しく書いてあります。 モニタリング本の基礎としてオススメです。

あとSHOW ENGINE INNODB STATUSについて詳しく知るには 実践ハイパフォーマンスMySQL を読むのがもっとも近道です。 また実践ハイパフォーマンスMySQLMySQLの振る舞いを深く知ることができますのでMySQL使いは必読です。 ちなみに僕はMySQLソースコード詳しいわけではないので実践ハイパフォーマンスMySQLを読んだ程度の SHOW ENGINE INNODB STATUS 力です。

というわけで SHOW ENGINE INNODB STATUS は怖くないのでぜひこの機会に使いこなしてみましょう。