目次
MariaDBのスロークエリログ（Slow Query Log）をテストで活用する
MariaDBの「スロークエリログ（Slow Query Log）」は指定した秒数以上の実行時間がかかるSQL文をログに記録してくれる機能です。
これはシステムの出荷前テストなどの時に有効にしておくと、とても役に立ちます。
今回は「スロークエリログ（Slow Query Log）」の使い方を使って気づいたポイントなどを補足しつつ書いてみようと思います。
なお、今回書く「使い方」は、僕がやっている使い方のみです。
他の「スロークエリログ（Slow Query Log）」の機能については、以下の本家のページに詳しく書いてあるので、あえて重複して書きません・・あしからず。
僕がテスト時に使っているiniファイルの設定
スロークエリログはファイル出力とテーブル出力（mysql.slow_log）ができますが、僕はファイル出力しか使わないので、そのていで書いてます。
ログ出力するだけなら、以下の４行だけでいいです。
slow_query_log
log_output=FILE
slow_query_log_file=c:\Mariadb\log\slow-queries.log
long_query_time=5.0
long_query_time=5.0は閾値です。
これ以上（例だと5秒）時間のかかるクエリをログに吐き出すわけです。
よく1.0とかなっている例を見ますけど、正直1.秒程度だと出力されすぎて、ポイントがずれるので、僕は5.秒程度にしてます。
続けてオプションです。
結構、頻繁に設定しているのがこちらです。
log_slow_admin_statements=OFF
log_slow_verbosity=explain
log_slow_admin_statementsをONにすると管理ステートメント（Create tableとか）もスロークエリログに含めてしまうのでOFFにしてます。
デフォルトがOFFなので書かなくてもいいのですが、念のため。
log_slow_verbosity=explainでと「Explain情報」をスロークエリログに出力してます。
ちなみに、query_planを書くと「クエリの実行プラン」も出力できますが、その分ログがごちゃごちゃするので、僕的にはexplainのみ使ってます。
続けて、たまに設定するものです。
log_queries_not_using_indexes=ON
min_examined_row_limit=100000
log_queries_not_using_indexes（インデックスを使っていないクエリをログに吐き出す）は、設定すると「スロー」でなくても、どこかでINDEXを使えていないクエリがあると出力されます。
有益なのですが、そのへんの規約がゆるい環境だと、ログファイルのサイズが大きくなって、ポイントとなるものを探しづらくなるデメリットもあるので、ケースバイケースで必要なときだけONにしてます。
min_examined_row_limitは、これより少ない行数を検査するクエリはログに吐き出さないという設定です。
こちらも、環境によっては設定すると有益な時があります。
なお、log_slow_rate_limitとlog_slow_filterは僕は使ったことがありません。
出力されたログファイルの見方
スロークエリログには以下のような情報が付与されます。
# Time: 2022-07-12T09:49:18.135730Z
# User@Host: hoge[hoge] @ hoge.local [192.168.1.1]
# Thread_id: 22 Schema: hoge_table QC_hit: No
# Query_time: 3.980892 Lock_time: 0.000043 Rows_sent: 0 Rows_examined: 0
# Rows_affected:8631 Bytes_sent: 55
各項目の意味は以下です。
- Query_time：クエリの実行時間（単位：秒)
- Lock_time：クエリの実行開始までの時間。他のスレッドのロックの待ち時間
- Rows_sent：クエリの命令文（ステートメント）が返す行数
- Rows_examined：操作対象となった行数
- Rows_affected： INSERT、 UPDATE、REPLACE 、 DELETE クエリで変更された行
- Bytes_sent:：クライアントに送信された合計バイト数
あと、explainオプションをつけているのと、以下のような情報も出力されます。
# explain: id select_type table type possible_keys key key_len ref
rows Extra
# explain: 1 SIMPLE nation ref PRIMARY,n_name n_name 26 const 1Using where; Using index
これはExplainの情報です。
１行目がヘダーで2行目以降に内容が出力されます。
JOINやUNIONをしているテーブルごとに行がわかれて評価されます。
正直、僕も精査まではしてないですが、ここに以下のような情報が表示されていると、ヤバい可能性があるので改善検討するようにはしてます。
- type列に「index（フルインデックススキャン。とても遅い）」または「ALL（フルテーブルスキャン。インデックスが利用されていない）」が表示されている。
- Extra列に「Using filesort（メモリではなく物理ファイルに書き出してソート）」や「Using temporary（クエリの実行にテンポラリテーブルを作った）」が表示されている。
そのほかにも色々ありますが、あまり欲張るとつらくなってしまうので、最低限チェックするのは上記の２つくらいで考えてます。
ちなみに、その他各項目の詳しい説明はこちらにあります。
スロークエリログの得手・不得手を意識する
スロークエリログには不得手もあります。
というか、個人的には、ほぼボトルネックになっている「Select」文にあたりをつけるために使っている感じです。
僕が使いこなせてないだけかもしれませんが、例えば「insert」処理だと、単発のinsert文をループで大量に実行していて遅いプログラムとかは、単発のinsert文ひとつひとつの実行時間が短いことから、スロークエリログであたりをつけるのは難しいです。
それを修正して「バルクインサート」するようにしたら、ひとつのクエリの実行時間がのびて逆にスロークエリログにのってきたりとかもしますしね。
でも、僕のように限定的に使っても、納品前のシステムでボトルネックになっているクエリにあたりをつけるヒントになる情報をもらえます。
なので、テスト環境では、とりあえずＯＮでよいのではないかと思います。
Ｉ／Ｏの負荷がかかるので、本番ではなかなか有効にしづらいのですけどね。
スロークエリログをテストで使うときのワンポイント
スロークエリログには「SQL文」しか出力されません。
当たりまえです。
なんですが・・。
問題のあるSQL分を、実際のテストで改善するためには「そのSQL文を生成・発行している」機能＝ソースコードを見つけないといけません。
意外にこれが大変です。
だから、テストしてるときに「遅いなあ」と思った機能があったら、機能名と動かした日時をメモってもらうようにしてます。
そうすることで「日付と時間」でスロークエリログで見る場所を絞り込めます、
もちろん、いつもいつも、それでうまく行くとは限りませんけど、何もしないよりは大分ましです。
特に複数人で分担してテストしてるときとかは必須ですね。
僕にとっては・・ですけど。
今回はこんなところで。
ではでは。
