実践ハイパフォーマンスMySQLが役にたったという話

概要

sennaの全文検索で処理が遅くなっているので直せって言われて直したときの話です。
いわゆる既存コードの改修です。

$ mysql --version
mysql  Ver 14.12 Distrib 5.0.87, for unknown-linux-gnu (x86_64) using readline 5.1

MASTER/SLAVEの一般的な構成
インデックスでSENNAを利用
ENGINEはMyISAM

MASTERのテーブル

hoge_wo

SLAVEのテーブル

hoge_wo
hoge_ro

MyISAMは書込みを行う際にテーブルロックを行います。
おそらくこの理由によって、書き込み用と読み込み用のテーブルを分けて設計されています。

数分毎にrename tableによって書込み、読み込みテーブルを入れ替えています。
このタイミングにあわせてCHANGE MATER TO を実行して各テーブルが前回行ったPOSITIONを入れなおします。

で、数分毎にこの処理を行っていて、このタイミングで高い確率でslow queryが発生し、このサービスの負荷が
高くなっているという事を突き止めました。

読み取りでI/O待ち

slow queryが発生していタイミングでvmstat, iostatを行ったところ、デバイスブロックの読み込みが多くなっていることに気づきました。
普段はこんな数値も

$ iostat -dx 5
Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
                  4.00    13.40 40.80 24.80  1164.80   305.60    22.41     0.28    4.30   2.86  18.76
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
                  4.00    13.40 40.80 24.80  1164.80   305.60    22.41     0.28    4.30   2.86  18.76
                  0.00     0.00 44.80 38.20  1164.80   305.60    17.72     0.32    3.90   2.26  18.74
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

slow queryが発生している状態

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
                  85.23   298.40 1002.99 106.19 49382.83  3254.29    47.46    15.57   14.09   0.90  99.82
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
                  85.23   298.40 1002.99 106.19 49382.83  3254.29    47.46    15.57   14.09   0.90  99.82
                  0.00     0.00 1086.23 406.79 49354.09  3254.29    35.24    19.61   13.36   0.67  99.82
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

Device:         rrqm/s   wrqm/s   r/s   w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util
                 97.40    38.80 636.20 132.00 53312.00  1369.60    71.18    19.46   25.45   1.30 100.02
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
                 97.40    38.80 636.20 132.00 53312.00  1369.60    71.18    19.46   25.45   1.30 100.02
                  0.00     0.00 732.00 171.20 53356.80  1369.60    60.59    23.10   25.68   1.11 100.02
                  0.00     0.00  0.00  0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

読み取りが発生する原因を特定して、slow queryと関係あるか調べる

この時点で問題が発生しているのは「rename table」によって読み取り、書込みテーブルを入れ替えている処理か、
もしくは数分前まで行っていたreplicationを再開する事によって発生しているのか、どちらかだと思いました。

なので次のようにこの処理の実行タイミングをずらしてみました。

rename_tables();
sleep(30);	# ここで少し休ませる
start_slave();

結果

rename_tables()を行った際に、若干読み取りI/Oが発生しました。そしてほんの少しslow queryが発生しました。

start_slave()を行った際に、しばらく読み取りがI/Oが発生しました。がslow queryは発生しませんでした。

考察

※この考察は嘘つきが書いているかも知れません…

rename_tables()でslow queryが発生している理由は、renameした時点でファイルシステム側のページキャッシュが無効になっていて、最初の全文検索時にsennaのインデックスファイルがバッファされていないことが理由だと思います。

start_slave()で読み取りが大量に発生しているのはよく分かりませんが、relay-logを読み込むでいるのかどうなのか。

では、sleep(30)で何が起きたのかを考えてみました。おそらくは以前は次のような状況だったんだと思います。

rename_tables()とstart_slave()が実行される
start_slaveによってしばらく読み込みが大量に発生
rename_tables()の後でselectが発生
sennaのインデックスファイルを読み込む、が同じ時間帯に読み込みが大量に発生しているので遅延する
続々selectを受け付ける
やっとインデックスファイルを読み込む、たまっていたクエリに返事をする。

でsleepによってsennaのインデックスファイルが読み込む時間が邪魔されなくなったんだと思います。

たぶん。