MySQLで、やたら重いクエリが発生したので、原因を究明するまでの話

MySQL

今後の為に原因の追求方法をメモ

まずは、どのクエリが重いのか調査


SHOW PROCESSLIST


実行中のプロセスが表示される
処理時間がTimeに表示されたり、実行中のコマンドがInfoに表示されるので、重い処理がどれだか判る


ちなみに、KILLコマンドで、処理中のプロセスを殺すことも可能

EXPLAIN SELECT でどんな風に検索されているか確認


今回は、indexがきちんと使われているか、確認の為に使用

+----+-------------+------------+-------+---------------+------------+---------+------+------+-------------+
| id | select_type | table      | type  | possible_keys | key        | key_len | ref  | rows | Extra       |
+----+-------------+------------+-------+---------------+------------+---------+------+------+-------------+
|  1 | SIMPLE      | test_table | index | NULL          | test_index | 4       | NULL |   10 | Using where |
+----+-------------+------------+-------+---------------+------------+---------+------+------+-------------+
  • typeがindexならば、indexが使われている
  • typeがALLならば、フルテーブルスキャン(重い)


MySQL :: MySQL 4.1 リファレンスマニュアル :: 5.2.1 EXPLAIN 構文（SELECT に関する情報の取得）


indexが使われているが、やたら重いのでボトルネックを確認する

SHOW PROFILE でクエリの処理毎の実行時間を見る


やたら重い箇所があったらそこがボトルネックなはず

mysql> SET profiling = 1;
mysql> SELECT ...
mysql> SHOW PROFILE;

+--------------------------------+------------+
| Status                         | Duration   |
+--------------------------------+------------+
| starting                       |   0.000081 | 
| checking query cache for query |   0.000484 | 
| Opening tables                 |   0.000052 | 
| System lock                    |   0.000020 | 
| Table lock                     |   0.000092 | 
| init                           |   0.000283 | 
| optimizing                     |   0.000137 | 
| statistics                     |   0.000052 | 
| preparing                      |   0.000089 | 
| executing                      |   0.000002 | 
| Sorting result                 |   0.000010 | 
| Sending data                   | 115.337027 | 
| end                            |   0.000066 | 
| query end                      |   0.000015 | 
| freeing items                  |   0.000201 | 
| storing result in query cache  |   0.000022 | 
| logging slow query             |   0.000001 | 
| logging slow query             |   0.033929 | 
| cleaning up                    |   0.000034 | 
+--------------------------------+------------+


Sending dataは、読み込みと絞りこみに掛かってる時間

This is quite a misleading status. It should be called "reading and filtering data".


MySQL :: MySQL 5.1 リファレンスマニュアル (オンラインヘルプ) :: 8.5.5.33 SHOW PROFILES 構文


普通に、検索結果をwhereするのに時間が掛かってる様子
この辺でMySQLのファイルが上手くキャッシュメモリに乗っていないのではないか? という疑惑が


vmstatコマンド で、disk ioを調査


disk io 等を調査できるlinuxのコマンド
詳しくはこっち → linuxで空きメモリがどんくらいあるか確認する方法 - かせいさんとこ


$ vmstat -SM 10
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    361      5      1    267    0    0     0     2  987   85  0  0 100  0  0

〜 検索開始 〜

 0  1    361      5      1    267    0    0   348     0 1024   90  1  2 55 43  0
 0  1    361      5      1    267    0    0   610     3 1128  192  0  3  0 97  0


SELECT文発行直後に、ディスクioが大量に発生して、さらにcpuのio待ち率が97%とかになってる!


調べてみたら、テーブル用のファイルがOSのディスクキャッシュより大きかったために、SELECT文を発行する度にHDDにアクセスしていたのが原因だった
今回は、テスト用の環境なので、データ量を減らす事で解決
ハマりました...

おまけ


MySQLのtable_cacheは、テーブルそのもののキャッシュではなく、テーブルに必要なファイルのハンドラをキャッシュする領域
テーブルそのもののキャッシュと勘違いしてました...