MySQLでバッチ処理を回すときはちゃんとflush tablesしましょうという話ですよ。。。

知ってる人には常識かも知れないですが、夜間バッチでまとめてDB処理なんかをする際、数時間プログラムを回しっぱなしにするケースは多いと思います。

自分の担当してるサービスでも毎日深夜に数時間回し続けるバッチがあり、毎日深夜になると定期的にロードアベレージが８とかになります。

こういう感じ

グラフをみてもわかるとおり、ピークタイムを過ぎるとＬＡはだいたい１、多くても２程度で推移するので、夜間以外は正常と判断してしばらく放置してました。

すると、ある日を境に何故かスワップを大量に消費し始めるようになりました。

ななな、何で？？

とりあえずスワップといえばvmstat

$ 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 0 1204 629960 58144 7135856 0 0 4 8 0 1 2 0 97 0 0
0 0 1204 630140 58144 7135856 0 0 0 0 2089 877 1 0 99 0 0
0 0 1204 630256 58144 7135860 0 0 0 0 1009 57 0 0 100 0 0
0 0 1204 630036 58152 7135852 0 0 0 68 2118 882 1 0 99 0 0
2 0 1204 630036 58152 7135852 0 0 0 0 1032 383 0 0 100 0 0
0 0 1204 630196 58152 7135860 0 0 0 0 2042 524 0 0 100 0 0
0 1 1204 630196 58156 7135856 0 0 0 140 2069 850 1 0 99 0 0

とくに怪しげなswapアウトは発生してない様子。

何故なんだぜ。
次に捜査線上に浮かんだのはInnoDB status。

実行

mysql> show innodb status;
=====================================
110412 9:43:47 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 928951282, signal count 716933241
Mutex spin waits 0, rounds 211020826974, OS waits 590498619
RW-shared spins 101663189, OS waits 49421755; RW-excl spins 50508270, OS waits 9177506
------------
TRANSACTIONS
------------
Trx id counter 0 3976676928
Purge done for trx's n:o < 0 3976676816 undo n:o < 0 0
History list length 8
--------
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
268095998 OS file reads, 53920683 OS file writes, 40435603 OS fsyncs
20.12 reads/s, 19024 avg bytes/read, 16.15 writes/s, 8.36 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 32763, seg size 32765,
2339689 inserts, 2339686 merged recs, 1578239 merges
Hash table size 4425293, node heap has 14515 buffer(s)
2739.13 hash searches/s, 704.22 non-hash searches/s

-

LOG

-

Log sequence number 153 59884262
Log flushed up to 153 59884262
Last checkpoint at 153 59254223
0 pending log writes, 0 pending chkp writes
38070529 log i/o's done, 5.85 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 2505081380; in additional pool allocated 18406912
Dictionary memory allocated 1196296
Buffer pool size 131072
Free buffers 0
Database pages 116557
Modified db pages 1996
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 508874812, created 1400785, written 19473238
23.36 reads/s, 0.27 creates/s, 10.45 writes/s
Buffer pool hit rate 998 / 1000
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 7288, id 1189693760, state: sleeping
Number of rows inserted 136262681, updated 18287724, deleted 21500, read 123593301785
3.58 inserts/s, 1.94 updates/s, 0.00 deletes/s, 4773.64 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

見る限りSによる書き込み待ちはなし、秒間16.15程度の書き込みで、バッファプールのヒット率も高く、インサート待ちキューも無い。
健康そのもののように思えるが・・・？

まったく原因がわからない。
原点に戻り、topしてmysqldのサイズを見ることに。

$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3934 mysql 15 0 9183m 7.5g 6576 S 158.4 21.2 1951:33 mysqld

あれ？？？
なんかmysqld膨らんでる。。。？

起動直後のmysqldと比べてみると

$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3934 mysql 16 0 3784m 2.6g 6516 S 171.8 7.3 30:15.76 mysqld

やっぱり増えてる！
本当にありがとうございました。

InnoDBまわりは正常なことが判ってるので、次に怪しいキャッシュ周りの設定を見なおしてみる。

mysql> show variables like 'query_cache_size';

------------------+-------+

Variable_name Value

------------------+-------+

query_cache_size 0

------------------+-------+

クエリキャッシュサイズは0だと効かないはず。

もしかしてと思い、今度はopen tableの数を確認。

mysql> show open tables;

-------------+-----------------------------------------+--------+-------------+

Database Table In_use Name_locked

-------------+-----------------------------------------+--------+-------------+

-------------+-----------------------------------------+--------+-------------+

256 rows in set (0.00 sec)

このサービスで使ってるテーブル数は140程度なのに、256もopenしてる！何故だ！！

なんて思う年はすでに卒業してるんだよね。私。
MySQLのヘルプにもわざわざ

テーブルが 6 つしかない場合に Open tables値が 12 と表示されることに、当惑する場合もあります。

って注釈してるように、open tablesはmax connectionに左右されます。
ということはこのサーバはオープンになったまま使ってないコネクションが残ってるのか。

それではということで、早速flush tablesを実行。

mysql> flush tables;

$ top
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
3934 mysql 15 0 6879m 5.3g 6576 S 0.0 15.1 2347:13 mysqldmysqld

仮想メモリが3G近く減った！
犯人はお前か！

しかしswapは思ったほどswapが消えなかった...orz
おそらくswapアウトした領域は現在のコネクションでは使われないデータが多かったということなんでしょう。

ただこれで、バッチのあとにflush tablesをするようにすればスワップアウトも抑止できるがわかったので、こまめにflushしましょう。
これって多分常識なんだよね。。。