LoginSignup
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

@tongari0(tongari)

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

Last updated at Posted at 2019-01-21

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の世界へようこそ

  1. ioDriveの副作用？ ioDrive入れたからベンチマークとってみたけど 全然性能でないし、なんかCPU詰まってる！ キャパシティ : 1600% ベンチマーク : 350% まで
  2. 犯人は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
1.PNG

ベンチマーク中にとった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
2.PNG

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

検証方法

  1. MySQLのコマンドでQueryCacheSizeを0に設定（MySQLのデフォルト値）
  2. shell scriptでvmstat,show stats,show processlistを毎秒取得
  3. mysqlslapを走らせ、終了まで待つ
  4. MySQLのコマンドでQueryCacheSizeを128MBに設定
  5. 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はデフォルト（無効）で使おう。

1
0
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
1
0

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?