MySQL 5.1のQueryCacheによるマルチコア環境での影響調査 #MySQL

2019.1.24追記

MySQLが遅いシステムは、結局、indexを使わないupdateクエリを投げているため、フルスキャンが走っていることが原因だった。それでも、CPUもメモリもあんまり使われていないのが腑に落ちない。。。1クエリ1スレッドのため、CPU使用率も平準化されるのだろうか。

2019.1.22追記

商用環境に適用しましたが、残念ながら遅いままでした。。。
よって、参考情報としての記事となります。

show processlist;で見ると、「Sending data」と表示された update a.b ignore index (b) c.d　クエリが5つほど、2桁～3桁のTimeで実行中で、SELECTクエリがLock状態。原因はなんなんだ。。。スワップしてないからNUMAじゃないし。。。

MySQL 5.1 (MyISAM) を使った古いシステムが日中とてつもなく遅い。
リクエストからレスポンスまで60秒で返ればいいほうで、タイムアウトになることがざらにある、、、

MySQLが遅いシステム - OSの調査

topやvmstatでわかったことは、以下の通り。

CPU16スレッドの使用率が平均30%くらいで余裕がある
I/O WaitやNetwork使用率も1桁台で問題なし
Load Averageが0.4と低いが、実行待ちプロセス数は4～8をうろうろ

つまり、ハードにボトルネックはない。
考えられるのは、ソフトがマルチコア非対応？　バッファ足りない？
indexが未設定でフルスキャンが走っているかもしれないけれど、そのときはCPUフルで使うのでは？

MySQLが遅いシステム - MySQLの調査

mysqlにログインしてshow processlistを見てみると、

updateクエリが何十秒も実行中
selectクエリがいくつもlock解除待ち

なんじゃこりゃ？　と思いぐぐってみると、QueryCacheはスケールしないという記事がいくつか見つかる。

クエリキャッシュは切ったほうがいいんじゃなイカ？

しかもクエリキャッシュの更新はグローバルなロックを取得する
たとえばユーザーの行動力のようなパラメータを格納した参照も更新も多いテーブルでクエリキャッシュが有効になっていると、せっかくたくさんコアを載せた高性能サーバーでも全然パフォーマンスが出なくなります。

グローバルなロックを取得した場合、UPDATEを4つ投げてもひとつずつしか処理できず、しかもひとつのSQLはひとつのスレッドでしか処理できない。
よって、マルチコアのCPUを載せていても、並列処理ができず、シングルスレッド並の性能しかでない、ということか。

第2回 ioDrive+MySQL勉強会 @外道父 ioDriveの世界へようこそ

ioDriveの副作用？ ioDrive入れたからベンチマークとってみたけど全然性能でないし、なんかCPU詰まってる！キャパシティ : 1600% ベンチマーク : 350% まで

犯人はquery_cacheでした query_cacheを無効にしたら最大までCPUが稼働しました

まさになんかCPU詰まってる感じ！！！

MySQL – ごく単純なUPDATEがなぜか遅い時がある

何回かshow processlistを実行していたら、変なやつが登場してきました。
その名も「Waiting for query cache lock」！

うちのshow processではみつからないけど、限りなくあやしい。。。

遅いシステムのmy.cnfにはQueryCacheSizeの設定が入っている。
では、どの程度QueryCacheが影響するんだろうと思い、本番適用前にmysqlslapを使って検証することにした。

結果

QueryCache有効だとめっちゃ遅くなる！！！

QueryCache無効

mysql> SET @@global.query_cache_size=0;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'query%';
+------------------------------+---------+
| Variable_name                | Value   |
+------------------------------+---------+
| query_alloc_block_size       | 8192    |
| query_cache_limit            | 1048576 |
| query_cache_min_res_unit     | 4096    |
| query_cache_size             | 0       |
| query_cache_type             | ON      |
| query_cache_wlock_invalidate | OFF     |
| query_prealloc_size          | 8192    |
+------------------------------+---------+
7 rows in set (0.00 sec)

[root@localhost ~]# ./slap2.sh 
Benchmark
        Running for engine myisam
        Average number of seconds to run all queries: 2.336 seconds
        Minimum number of seconds to run all queries: 2.302 seconds
        Maximum number of seconds to run all queries: 2.358 seconds
        Number of clients running queries: 10
        Average number of queries per client: 10000

ベンチマーク中にとったshow full processlistを見ていく。
まず、グラフで0:00:02のとき、ひとつのINSERTクエリが走っている。ここでのCPU使用率は40%いかない程度。

2171        root    localhost       mysqlslap       Query   0       closing tables  INSERT INTO t1 VALUES (NULL,840098998,1711081283,898581402,408461159,1316988559,1222118486,276120047,1045280395,1270820277,1209004130,'QOPe8XYkIYviP1FTsAJh99xj88Av4zmMN30NQO7kwvIEoZjgcuEd43LCBN07MeTdhT07uzkiu2wiSXFwQLPMOmab9QbN440dQsdCsLueFjDbESXYhxu5bLYdf70k4t','LWlyiTBc8RBL2QhQqMFdRqqrJTzC535RZiH7CTjCwvZqDEGvcXOvEEmZcdlhYi8xHQ4LngZjR6ZgCiRo5sbJyLlarW8N5GLMaPjL5GwOEMwQ4O698hL6u6ZlSh9PpM','nGfMTdWQ1kgy2kM8lWhySc41DPaMqOcWgGk9tFRuz7sur62TScRxCOqHhPYNp8lLOWWHly4cxwWhvPAN1TC5l3MIKmi9vRMJpkTaiZ3YLZDGqNgjksgMn3g7pM8ciW','wXFHypq1LBQaSHp00ashwgccnHrwmPIioZrmNhnck6BCN0CFQxoEdGjGQa4CrNufwlQBI5o2Br7QrBaA8MOdX7uxZq9ODv42YM5qRtkXcrxKvNW3euZ9uJ6J9FkF2g','Ha2EGT00sckiwf5QajDzszIqISx2bzakZcypyyiqbIONpWqN5vFquZg4tezSdZC3A3k01QiSc7sPTahaTwGFTxJFRIjwsozurcmsuSDXR5wwfTN8PfFnSa2vtdkdPb','N8B9t6d6d53PtivGiCoxr8Xt4GNglgF8pRHaZvg2sjRdHEuzRaoIiB4eKJI5zQEgtXEIImCALfoemaT509NiLJDhWNmWp02iO9siv4l9cPnMr9RrIiPXueCO2rmrjh','Q7qAqdFbmjsQ5jROal6r90WLHO43FokZvQkd4r4iaw0XfRv551xEuJRBjY6qCrO790lDrhwHeoo9GjFLc4RWNuZ6IYwWFCeO4FevoQ4QEscMRjb4f2Q2x007Yoen18','35Nht3zpW6iyS9Z45CyY6vO63ouZRnhWlwCWz3JL91JW3kQ8wOY2Cw07kvgBaLiJ9mp8p1Wr2hDxQfyMvWH7RH6B4mNXzxq8jY9OZf7RKKHerFtnlAmCJtGGXXnXST','XB1gRQBbmOn32fIvI3xw8HpOZDvKcFp7Ijgl1jKn70qAf8xx4vtCCbSdgFpGWWFo5nP7Xeueelg9leypZjtdIL6ySv6qHMWN9wWYaOB41jDnLBSmuMF5bLvw82mQGH','pHDJqfbtbTco8qrcSlqciIpeEyY0OgH5xMGftjYSC1GKrzpBdfnJxdp3bD4rtDojcwETffqkgy4NylabPEmErcIIhE1RRh2vdGHGv70bxxyviPMzf96MdGgIWZlpEn')

で、0:00:08のとき、複数のSELECTクエリが走っている。ここではばっちりCPUを使い切ってくれている！

2182        root    localhost       mysqlslap       Query   0       Writing to net  SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '70367'
2183        root    localhost       mysqlslap       Query   0       statistics      SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '83375'
2184        root    localhost       mysqlslap       Query   0       Writing to net  SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '1983'
...

QueryCache有効

mysql> SET @@global.query_cache_size=128*1024*1024;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'query%';
+------------------------------+-----------+
| Variable_name                | Value     |
+------------------------------+-----------+
| query_alloc_block_size       | 8192      |
| query_cache_limit            | 1048576   |
| query_cache_min_res_unit     | 4096      |
| query_cache_size             | 134217728 |
| query_cache_type             | ON        |
| query_cache_wlock_invalidate | OFF       |
| query_prealloc_size          | 8192      |
+------------------------------+-----------+
7 rows in set (0.00 sec)

 [root@localhost ~]# ./slap2.sh 
Benchmark
        Running for engine myisam
        Average number of seconds to run all queries: 10.559 seconds
        Minimum number of seconds to run all queries: 10.488 seconds
        Maximum number of seconds to run all queries: 10.613 seconds
        Number of clients running queries: 10
        Average number of queries per client: 10000

0:00:02のINSERTクエリ。こちらはQC無効時と傾向はかわらない。

2471        root    localhost       mysqlslap       Query   0       closing tables  INSERT INTO t1 VALUES (NULL,840098998,1711081283,898581402,408461159,1316988559,1222118486,276120047,1045280395,1270820277,1209004130,'QOPe8XYkIYviP1FTsAJh99xj88Av4zmMN30NQO7kwvIEoZjgcuEd43LCBN07MeTdhT07uzkiu2wiSXFwQLPMOmab9QbN440dQsdCsLueFjDbESXYhxu5bLYdf70k4t','LWlyiTBc8RBL2QhQqMFdRqqrJTzC535RZiH7CTjCwvZqDEGvcXOvEEmZcdlhYi8xHQ4LngZjR6ZgCiRo5sbJyLlarW8N5GLMaPjL5GwOEMwQ4O698hL6u6ZlSh9PpM','nGfMTdWQ1kgy2kM8lWhySc41DPaMqOcWgGk9tFRuz7sur62TScRxCOqHhPYNp8lLOWWHly4cxwWhvPAN1TC5l3MIKmi9vRMJpkTaiZ3YLZDGqNgjksgMn3g7pM8ciW','wXFHypq1LBQaSHp00ashwgccnHrwmPIioZrmNhnck6BCN0CFQxoEdGjGQa4CrNufwlQBI5o2Br7QrBaA8MOdX7uxZq9ODv42YM5qRtkXcrxKvNW3euZ9uJ6J9FkF2g','Ha2EGT00sckiwf5QajDzszIqISx2bzakZcypyyiqbIONpWqN5vFquZg4tezSdZC3A3k01QiSc7sPTahaTwGFTxJFRIjwsozurcmsuSDXR5wwfTN8PfFnSa2vtdkdPb','N8B9t6d6d53PtivGiCoxr8Xt4GNglgF8pRHaZvg2sjRdHEuzRaoIiB4eKJI5zQEgtXEIImCALfoemaT509NiLJDhWNmWp02iO9siv4l9cPnMr9RrIiPXueCO2rmrjh','Q7qAqdFbmjsQ5jROal6r90WLHO43FokZvQkd4r4iaw0XfRv551xEuJRBjY6qCrO790lDrhwHeoo9GjFLc4RWNuZ6IYwWFCeO4FevoQ4QEscMRjb4f2Q2x007Yoen18','35Nht3zpW6iyS9Z45CyY6vO63ouZRnhWlwCWz3JL91JW3kQ8wOY2Cw07kvgBaLiJ9mp8p1Wr2hDxQfyMvWH7RH6B4mNXzxq8jY9OZf7RKKHerFtnlAmCJtGGXXnXST','XB1gRQBbmOn32fIvI3xw8HpOZDvKcFp7Ijgl1jKn70qAf8xx4vtCCbSdgFpGWWFo5nP7Xeueelg9leypZjtdIL6ySv6qHMWN9wWYaOB41jDnLBSmuMF5bLvw82mQGH','pHDJqfbtbTco8qrcSlqciIpeEyY0OgH5xMGftjYSC1GKrzpBdfnJxdp3bD4rtDojcwETffqkgy4NylabPEmErcIIhE1RRh2vdGHGv70bxxyviPMzf96MdGgIWZlpEn')

0:00:08のSELECTクエリ。なんとCPU使用率が落ち込む！

2483        root    localhost       mysqlslap       Query   0       init    SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '29930'
2484        root    localhost       mysqlslap       Query   0       freeing items   SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '63499'
2485        root    localhost       mysqlslap       Query   0       NULL    SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '16266'
...

※ただし、遅くなったのはauto-generate-sql-load-type=keyの場合。その他のmixedやwriteなどの条件では変わらなかった。たぶん、MyISAMは書き込み系のクエリ実行時はテーブルロックするからかと。

検証環境

ESXi 6.0で作った以下のVM（遅いシステムに合わせたのでOS古いです）

Intel(R) Core(TM) i5-2500S CPU @ 2.70GHz (4 cores)
MemTotal: 8062732 kB
Red Hat Enterprise Linux Server release 6.1 (Santiago)
mysql Ver 14.14 Distrib 5.1.52, for redhat-linux-gnu (x86_64) using readline 5.1

検証方法

MySQLのコマンドでQueryCacheSizeを0に設定（MySQLのデフォルト値）
shell scriptでvmstat,show stats,show processlistを毎秒取得
mysqlslapを走らせ、終了まで待つ
MySQLのコマンドでQueryCacheSizeを128MBに設定
2 ~ 3をする

グラフは上記でとった時刻付ログを、同じ時刻同士に整形してExcelで作成した。

my.cnf

[root@localhost ~]# cat /etc/my.cnf
[mysqld]
disable-innodb
#query_cache_size=4M
#performance_schema=on
datadir=/var/lib/mysql
socket=/var/lib/mysql/mysql.sock
user=mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links=0

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

mysqlslap

[root@localhost ~]# cat ./slap2.sh 
mysqlslap \
 --no-defaults --auto-generate-sql --engine=myisam --auto-generate-sql-add-autoincrement \
 --host=localhost --port=3306 -u root \
 --number-int-cols=10 \
 --number-char-cols=10 \
 --iterations=10 \
 --concurrency=10 \
 --auto-generate-sql-write-number=100000 \
 --number-of-queries=100000 \
 --auto-generate-sql-load-type=key

show status

[root@localhost ~]# cat stats.sh 
#!/bin/bash

#mysql -u root show status;

while :
do 
  _line=`echo 'show status' | mysql -u root`
  _date=`date '+%Y/%m/%d %H:%M:%S'`

  echo "${_line}" | while read line
  do
      echo "${_date} $line"
  done
  sleep 1
done

実行結果

2019/01/21 00:24:04 Variable_name       Value
2019/01/21 00:24:04 Aborted_clients     1
2019/01/21 00:24:04 Aborted_connects    0
2019/01/21 00:24:04 Binlog_cache_disk_use       0
2019/01/21 00:24:04 Binlog_cache_use    0
...

show processlist

[root@localhost ~]# cat processlist.sh 
#!/bin/bash

#mysql -u root show full processlist;

while :
do 
  _line=`echo 'show full processlist' | mysql -u root`
  _date=`date '+%Y/%m/%d %H:%M:%S'`

  echo "${_line}" | while read line
  do
      echo "${_date} $line"
  done
  sleep 1
done

実行結果

2019/01/21 00:24:12 2181        root    localhost       NULL    Query   0       NULL    show full processlist
2019/01/21 00:24:13 Id  User    Host    db      Command Time    State   Info
2019/01/21 00:24:13 2171        root    localhost       mysqlslap       Sleep   1               NULL
2019/01/21 00:24:13 2182        root    localhost       mysqlslap       Query   0       Writing to net  SELECT intcol1,intcol2,intcol3,intcol4,intcol5,intcol6,intcol7,intcol8,intcol9,intcol10,charcol1,charcol2,charcol3,charcol4,charcol5,charcol6,charcol7,charcol8,charcol9,charcol10 FROM t1 WHERE id =  '70367'
...

vmstats

vmstat -n 1 | gawk '{ print strftime("%Y/%m/%d %H:%M:%S"), $0 } { fflush() }'

実行結果

2019/01/21 00:23:58 procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----
2019/01/21 00:23:58  r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
2019/01/21 00:23:58  1  0      0 7480888  58500 201656    0    0     0     0   88   66  1  0 98  0  0   
2019/01/21 00:23:59  0  0      0 7480244  58500 201660    0    0     0     0  148   90  0  0 100  0  0  
2019/01/21 00:24:00  0  0      0 7480096  58500 201660    0    0     0     0  282  210  0  0 100  0  0  
...

結論

MySQLのQueryCacheはデフォルト（無効）で使おう。