DBが遅い！そんな時・・MySQL スロークエリーからの索引チューニング〜 mysqldumpslow

f:id:hit10231023:20180309104332j:plain

MySQL/MariaDBでのパフォーマンス低下一番の理由がスロークエリーです。MySQLでサービスを展開しているデータベースやさんって、例外なくここをきにするのではないかな？と思います。そしてスロークエリーが発生した場合の一番の対策は、適切な索引(INDEX）を設定という部分になると思います。たぶんですが、ディスクをSSDにすればー。とか、CPUのクロックをあげればとか、そもそもこのサーバでは古いとか・・・の前にまず索引のチューニングをするのが先って感じです

ここでは、

スロークエリをログファイルとして出力させるためのMySQL (MariaDB)の設定方法と
出力されたスロークエリを集計するmysqldumpslow ユーティリティについて説明したいと思います

ここでは、遅いクエリーをどう改善するかについての説明は割愛します。１つの例としてのチューニングについては、

hit.hateblo.jp

をご参照ください。

スロークエリの出力設定

あ、まず、mysqldumpslowを利用する前に必ず必要なのが、スローログファイルの出力設定です。スローログファイルを出力するためにはMySQLでの設定が必要になります

設定が必要なMySQLパラメータは以下の通りです

long_query_time

下記の場合、1.5秒以上経過したクエリーがスロークエリーと反映されます、ここの設定は、サービスによりけりなのですが、WEBサービスで利用するデータベースで、1.5秒は、遅いと私は思います。1.5秒でこれが何十回、何百回、何千回と発行されれば、地獄級の遅さになります。厳密にいうと、サーバマシンのロードアベレージが急上昇し、MySQLの前に、サーバのCPUに待ちが発生するようになります。まぁ結果的には遅くなるってことです。スロークエリー判定はもっと厳しくいきましょう

mysql>
SHOW GLOBAL VARIABLES LIKE '%query_time%' ;
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.500000 |
+-----------------+----------+

てなわけで、ここは、0.5秒に直します。0.5秒以上かかるクエリーはスロークエリーとして判定させます

mysql>
SET GLOBAL long_query_time = 0.5 ;

 SHOW GLOBAL VARIABLES LIKE '%query_time%' ;
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.500000 |
+-----------------+----------+

ONDA V820w CH 最新CPU Cherry Trail搭載Windows10 ２GB 32GB 8インチタブレット

出版社/メーカー: ONDA
メディア:
この商品を含むブログを見る

slow_query_log,slow_query_log_file

long_query_timeの設定をしたところで、slow_query_log のスイッチをONにしない限りは、何も出力してくれません。

mysql>
 SHOW GLOBAL VARIABLES LIKE '%slow_query%' ;
+---------------------+------------------------+
| Variable_name       | Value                  |
+---------------------+------------------------+
| slow_query_log      | OFF                    |
| slow_query_log_file | ip-10-0-1-123-slow.log |
+---------------------+------------------------+

こちらの設定をONにします

mysql>
 SET GLOBAL slow_query_log = 'ON' ;
-- ついでにスローログのファイル名も変更してみます
 SET GLOBAL slow_query_log_file = '2016-05-20-slow.log' ;
+---------------------+---------------------+
| Variable_name       | Value               |
+---------------------+---------------------+
| slow_query_log      | ON                  |
| slow_query_log_file | 2016-05-20-slow.log |
+---------------------+---------------------+

変更内容を反映

実は、設定しただけでは即座に反映しません。設計を反映させるためには、FLUSH LOGS コマンドをたたく必要があります

mysql>
FLUSH LOGS ;

やさしく学べるMySQL運用・管理入門【5.7対応】

my.cnf （server.cnf）の設定

上記設定で反映はされるのですが、次回MySQLを再起動するケースがあった場合、上記設定が初期化されてしまいますので、my.cnfファイルを事前に編集しておきましょう

vi my.cnf
------------------------------------
[mysqld]
slow_query_log
slow_query_log_file = 2016-05-20-slow.log
long_query_time = 0.5

こんな感じで書いておけば、次回再起動時も安心です。以降 MySQLは、0.5秒以上かかるクエリーをログファイルに吐き続けます

スローログを集計する

しばらく、数時間、いや、数日だったら、集計をしてみましょう。上記で作成した2016-05-20-slow.log で出力されているスロークエリーがどれくらいの頻度で発生しているのかを集計します

mysqdumpslowを発行

出力されたログをパラメータにして、mysqldumpslowを発行します。ここでは、集計結果を、 /tmp/slow_summary.logにしております

# mysqldumpslow 2016-05-20-slow.log > /tmp/slow_summary.log

出力結果確認

以下のようになりました

cat  /tmp/slow_summary.log

Count: 1000  Time=1.52s (0s)  Lock=0.00s (0s)  Rows_sent=20432.0 (20432), Rows_examined=64454.0 (64454), user001[user001]@[10.0.1.111]
 SELECT A,B,C FROM TABLE_A WHERE A = 'S'

Count: 10  Time=0.52s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=17.0 (17), user001[user001]@[10.0.1.123]
 SELECT A,B,C FROM TABLE_A WHERE B = N

Count: 110000  Time=3.42s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=17.0 (17), user001[user001]@[10.0.1.123]
 SELECT A,B,C FROM TABLE_A WHERE C = N

各項目の意味は以下のようになります

Count : SQLが発行された件数
Time : 平均クエリー実行時間
Lock: ロックしていた時間
Rows_sent: 読取り/更新したレコード数の平均。カッコの中は合計
Rows_examinedは論理読み取りの件数カッコの中は合計。

また、クエリー内にNとかSとかが入っていると思いますがこれが、N:数値、 S:文字列を表します結果このクエリから、索引が利用されているのか？そもそも索引が設定されているのか調べるわけですね。ただ、上記の例では３件ですが、ものによっては、数百数千件でる可能性もあります。そんなとき、私はオプションをつけて、結果をソートします

特によく使うのがソートオプションです。

こんな感じで利用します

mysqldumpslow -s c 2016-05-20-slow.log > /tmp/slow_summary.log

以下のようにCount: の多い順で出力されていることが確認できたかと思います

Count: 110000  Time=3.42s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=17.0 (17), user001[user001]@[10.0.1.123]
 SELECT A,B,C FROM TABLE_A WHERE C = N
Count: 1000  Time=1.52s (0s)  Lock=0.00s (0s)  Rows_sent=20432.0 (20432), Rows_examined=64454.0 (64454), user001[user001]@[10.0.1.111]
 SELECT A,B,C FROM TABLE_A WHERE A = 'S'
Count: 10  Time=0.52s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=17.0 (17), user001[user001]@[10.0.1.123]
 SELECT A,B,C FROM TABLE_A WHERE B = N

1つの長時間実行クエリを対策を優先するより、発行件数の多いものを優先して対応したほうが改善が速いです。頻度の少ない長時間実行クエリーは、あとでじっくり見ましょう。

そのほかのソートオプションは以下の通りになります

ソートオプション

al : 平均ロックタイムの長い順
ar  : 平均行数の多い順
at : 平均実行時間の長い順
c : クエリ発行数の多い順
l :  総ロックタイムの長い順
r :  総行数の多い順
t : 総実行時間の長い順

ちょっと、長々説明しましたが、こんな感じです

mysqdumpslowは上記以外のオプションもありますが、今回の説明では、ソートのみ書きました。その他のオプション利用方法については、下記をご参照ください

MySQL :: MySQL 5.6 リファレンスマニュアル :: 4.6.9 mysqldumpslow — スロークエリーログファイルの要約

Database JUNKY

MySQL,MariaDBを中心としたブログです