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 STATUS\G
*************************** 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)
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (write thread)
Pending normal aio reads: 0, aio writes: 0,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
2357511 OS file reads, 2899006 OS file writes, 2135241 OS fsyncs
1.00 reads/s, 1048576 avg bytes/read, 5.50 writes/s, 4.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 62475, seg size 62477,
1377324 inserts, 1408585 merged recs, 189783 merges
Hash table size 12750011, used cells 11829703, node heap has 49423 buffer(s)
15739.13 hash searches/s, 17208.40 non-hash searches/s
---
LOG
---
Log sequence number 749 970777392
Log flushed up to 749 969710928
Last checkpoint at 749 28529081
0 pending log writes, 0 pending chkp writes
2037285 log i/o's done, 2.50 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 7220366746; in additional pool allocated 1048576
Buffer pool size 393216
Free buffers 0
Database pages 343792
Modified db pages 39258
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 11227150, created 1300663, written 2491219
63.97 reads/s, 85.96 creates/s, 31.98 writes/s
Buffer pool hit rate 1000 / 1000
--------------
ROW OPERATIONS
--------------
1 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 3424, id 1169066304, state: sleeping
Number of rows inserted 70683515, updated 4112385, deleted 2976, read 1313233607
5462.27 inserts/s, 0.00 updates/s, 0.00 deletes/s, 5462.77 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================1 row in set (0.02 sec)
メモリ関連という仮説をOS周りの調査でたてましたので、ここでは「BUFFER POOL AND MEMORY」に注目します。
Free buffersが0、Buffer pool hit rateは100%です。
Free buffersが0ということで、バッチ処理中にbuffer poolを使い切っている可能性がありますが、Buffer pool hitは100%で効率はいいようですし、buffer pool sizeをこれ以上割り当てるかどうかは、ここでは短絡的に判断せず、総合的に考えようと思います。
次に「FILE I/O」をみてみます。秒間5.5回のHDDへの書き込みしか発生していないため、先ほどのvmstat結果での仮説、CPUのwait、ブロックを受けているプロセス発生の原因はDBのHDDへの書き込みが原因ではなくメモリのスワップによるものであることを間接的に示しています。また読込も秒間1回です。InnoDBに関連したデータはうまくメモリ上に乗っているのでしょう。
うーん、よくわからなくなってきました。
再びOSのレイヤーに立ち返って、MySQLの使用メモリ量を確認します。
[kou@db ~]$ ps -axl --sort -vsize
F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND
4 3306 3424 2218 15 0 7767024 6651556 stext Sl ? 220:05 mysqld --defaults-file=/etc/my.cnf --datadir=****
5 80 2239 2225 15 0 168036 800 - S ? 0:00 /usr/local/bin/httpd -DNO_DETACH
5 80 2241 2225 15 0 167984 928 - S ? 0:00 /usr/local/bin/httpd -DNO_DETACH
snip;
mysqldのRSSとVSZをチェックします。仮想的に確保されているメモリ量（VSZ）が約7.4GB、物理メモリに実際に確保されているメモリ量（RSS）が約6.3GBです。このサーバの物理メモリ量が8GBですから、他のプロセスが利用するメモリも考えるとなんとなく怪しいです。MySQLにメモリを割当過ぎなのかもしれません。
どうやら調べてみるとMySQLでは設定ファイルで割り当てたinnodb_buffer_pool_sizeよりも実際はもう少し大きく確保されるようです。
ここは試しにinnodb_buffer_pool_sizeを6GBから5GBに縮小してみます。
MySQL再起動後、psコマンドでMySQLの使用メモリ量を確認します。
[kou@db ~]$ ps -axl --sort -vsize
F UID PID PPID PRI NI VSZ RSS WCHAN STAT TTY TIME COMMAND
4 3306 3749 2218 15 0 6609584 6099176 stext Sl ? 30:36 mysqld --defaults-file=/etc/my.cnf
5 80 31423 2225 15 0 172448 17456 - S ? 0:02 /usr/local/bin/httpd -DNO_DETACH
5 80 2238 2225 15 0 171996 15040 - S ? 0:02 /usr/local/bin/httpd -DNO_DETACH
snip;
VSZとRSSがほぼ同じになりました。だいたい6GBを使ってます。同時に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 1 62116 46404 157372 1676080 20 17 906 936 1 11 6 1 68 25 0
0 0 62116 46404 157388 1676212 0 0 32 256 1068 157 1 0 92 8 0
0 0 62116 45164 157416 1677100 0 0 88 1896 1080 141 1 1 90 9 0
0 0 62116 45164 157448 1677216 0 0 0 324 1048 106 0 1 90 10 0
0 0 62116 45164 157464 1677176 0 0 28 184 1051 126 1 0 91 9 0
si/soが全くなくなりました。また、swpdが多少はありますが、しばらくモニタをしても増えたりはしません。
その後、問題のバッチ処理を流してみたところsi/soは発生せず、swpdの値にも変化はありません！
| 物理メモリ | 8GB→8GB |
| innodb_buffer_pool_size | 6GB→5GB |
| スワップ使用量（swpd） | ほぼ0 |
結論としてはメモリ増設の結果、調子に乗ってMySQL（innodb_buffer_pool_size）にメモリを割り当てすぎてしまったため、サーバ全体でみたときのメモリ割当のバランスを崩してしまっていたようです。
メモリも単純に増やせばいいってことではないんですね。いい勉強をしました。
日時: 2009年09月07日 19:40
