MySQLでInnoDB、バランスを取り戻せ!

こんにちわ、kouです。
今日もMySQLのInnoDBにまつわる失敗談です。
1000万行を超える複数のテーブルに対して複雑なSQLを発行しデータを整形するバッチの稼働時間の遅延が大きな問題となっているシステムがありました。このバッチが一定時間に処理が終わらないと後続バッチに影響が出てしまうため、早急な対応が必要です。
その過程で経験した失敗を恥ずかしいのですが、書いてみました。
初日
このようなバッチ処理遅延に対して、複雑(=効率の悪い)SQLチューニングも並行して行いますが、対応に時間がかかるため、まずはOS、ミドルウェアのチューニングで対応できないか検討をはじめました。
多くの議論があると思いますが、
「ボトルネック調査は下のレイヤーから!」
をモットーとしているため、まずはハードウェア、OSレベルから調査をはじめます。
# 今回のバッチ処理はlocalhostで閉じてますので、ネットワークは調査対象から除外です。
vmstat、freeコマンドで調べたところ悩むことなくボトルネック発見。大量にスワップが発生してました。サーバにはメモリスロットがまだ空いてますので、「メモリを増やしましょう」ということで即決。幸い予備のメモリが4GBありましたのでサクッと増設完了。
バッチプログラムはSQL文を発行するだけですし、他にメモリを消費するプロセスもないことからinnodb_buffer_pool_sizeは増設分をそのまま豪華に割り当てます。
やれやれ、ということで初日の対応が終了。

初日のカルテ
物理メモリ 4GB→8GB
innodb_buffer_pool_size 2GB→6GB
スワップ使用量(swpd) 約2GB


二日目
バッチ処理遅延のアラートで起床。
なんとバッチ処理時間がメモリ増設前より悪くなってる!
軽くパニックです。
再びボトルネック調査。
vmstatで観察するとまたもやスワップが発生しています。しかも前より激しく。。

[kou@db ~]$ vmstat 1
procs ———–memory———- —swap– —–io—- –system– —–cpu——
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 3 4195528 48920 9256 1238936 135 119 848 734 12 31 5 1 65 29 0
0 1 4196680 47104 9308 1242496 196 2500 4424 2600 1519 288 10 2 46 41 0
0 3 4196680 46980 9312 1242492 0 0 0 68 1008 24 0 1 50 50 0
0 1 4196864 46856 9348 1243540 228 912 3364 988 1201 233 6 1 44 48 0
0 1 4196828 46016 9364 1244496 96 0 1120 32 1038 100 1 0 38 61 0
0 4 4197308 46964 9356 1244720 272 1580 2048 1716 1275 216 6 1 45 49 0
0 2 4198220 48884 9372 1244464 12 1920 396 1964 1483 86 1 1 29 69 0
0 2 4198220 48884 9372 1244464 0 0 0 0 1006 25 0 1 49 50 0
0 1 4198136 48044 9420 1245440 92 0 1116 140 1051 138 3 0 45 52 0

スワップ使用量(swpd)が約4GBでsi/soが激しく繰り返されスラッシングが発生していることがわかります。CPUはアイドル(id)がほとんどですが、ウェイト(wa)が発生していることも確認できます。同時にI/O待ち(b)となっているプロセスも発生しています。
waとbだけをみた限りではSQLによるデータ更新量が大きく、DBのディスクI/O待ちの可能性もありますが、今回はsi/soが頻発し、swpdの値が大きいことからスワップに関するメモリの問題であることが推測されます。

OSレベルの調査を終え、次は調査対象レイヤーを一つ上げることにします。
「ボトルネック調査は下のレイヤーから!」
です。
MySQLに接続し、InnoDBの様子を観察します。

mysql> SHOW ENGINE INNODB STATUSG
*************************** 1. row ***************************
Status:
=====================================
090720 9:31:10 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 2 seconds
———-
SEMAPHORES
———-
OS WAIT ARRAY INFO: reservation count 360773, signal count 357635
Mutex spin waits 0, rounds 6498599, OS waits 84465
RW-shared spins 439505, OS waits 214581; RW-excl spins 34101, OS waits 15355
————
TRANSACTIONS
————
Trx id counter 0 487637839
Purge done for trx’s n:o < 0 487637607 undo n:o < 0 0 History list length 1 Total number of lock structs in row lock hash table 99 LIST OF TRANSACTIONS FOR EACH SESSION: ---TRANSACTION 0 0, not started, process no 3424, OS thread id 1169332544 MySQL thread id 11166, query id 14476783 localhost root SHOW ENGINE INNODB STATUS ---TRANSACTION 0 487637838, ACTIVE 2 sec, process no 3424, OS thread id 1091868992 inserting, thread declared inside InnoDB 341 mysql tables in use 2, locked 2 101 lock struct(s), heap size 14320, undo log entries 9850 MySQL thread id 11193, query id 14476349 172.16.49.76 batch copy to tmp table create index receipt_analysis_uid_idx on analysis.receipt_analysis(uid)


Comments are closed.