今日は、MySQL のスロークエリーが判定されるのに順序があるみたいの日。
目次
- 目次
- とある日
- スロークエリー判定順序
- 概要
- 関係するパラメータ
- 動作検証
- 比較順序
- 1. クエリーは管理ステートメントでないか、log_slow_admin_statements が有効になっている必要がある。
- 2. クエリーに少なくとも long_query_time 秒かかっているか、log_queries_not_using_indexes が有効であって、クエリーは行参照にインデックスを使用していない。
- 3. クエリーは少なくとも min_examined_row_limit 行を検査している必要がある。
- クエリーは、log_throttle_queries_not_using_indexes 設定によって抑制されていてはならない。
- まとめ
- 〆
- 参考情報
とある日
スロークエリーでパラメータの有効無効で記録されるクエリに違いがでることをしったので検証してみました。
スロークエリー判定順序
スロークエリーとは？設定方法とは？みたいな基本的なことは書いてないです。
概要
MySQL :: MySQL 8.0 リファレンスマニュアル :: 5.4.5 スロークエリーログ
- クエリーは管理ステートメントでないか、
log_slow_admin_statementsが有効になっている必要がある。 - クエリーに少なくとも
long_query_time秒かかっているか、log_queries_not_using_indexesが有効であって、クエリーは行参照にインデックスを使用していない。 - クエリーは少なくとも
min_examined_row_limit行を検査している必要がある。 - クエリーは、
log_throttle_queries_not_using_indexes設定によって抑制されていてはならない。
関係するパラメータ
log_slow_admin_statements
スロークエリーログに書き込まれるステートメントにスロー管理ステートメントを含めます。 管理ステートメントには、
ALTER TABLE、ANALYZE TABLE、CHECK TABLE、CREATE INDEX、DROP INDEX、OPTIMIZE TABLE、およびREPAIR TABLEが含まれます。
long_query_time
クエリーの時間がこの秒数よりかかると、サーバーは Slow_queries ステータス変数を増やします。 スロークエリーログが有効な場合、クエリーはスロークエリーログファイルに記録されます。 この値は CPU 時間でなくリアルタイムで測定されるため、負荷の軽いシステムでしきい値を下回るクエリーが、負荷の重いシステムではしきい値を超える場合もあります。 long_query_time の最小値およびデフォルト値は、それぞれ 0 および 10 です。 値はマイクロ秒の精度まで指定できます。 セクション5.4.5「スロークエリーログ」を参照してください。
この変数の値を小さくすると、長時間実行とみなされるステートメントが増えるため、スロークエリーログに必要な領域が増えます。 非常に小さい値 (1 秒未満) の場合、ログは非常に大きくなることがあります。 長時間実行とみなされるステートメントの数を増やすと、特にグループレプリケーションが有効になっている場合に、MySQL Enterprise Monitor の「「長時間実行プロセスの数が多すぎます」」アラートに対して誤検出が発生する可能性もあります。 これらの理由から、非常に小さい値はテスト環境でのみ使用するか、本番環境では短期間のみ使用する必要があります。
log_queries_not_using_indexes
スロークエリーログを有効にしてこの変数を有効にすると、すべての行を取得すると予想されるクエリーがログに記録されます。 セクション5.4.5「スロークエリーログ」を参照してください。 このオプションは、インデックスが使用されないことを必ずしも意味するわけではありません。 たとえば、フルインデックススキャンを使用するクエリーはインデックスを使用しますが、インデックスは行数を制限しないため、クエリーはログに記録されます。
min_examined_row_limit
これよりも少ない行数を検査するクエリーは、スロークエリーログに記録されません。
log_throttle_queries_not_using_indexes
log_queries_not_using_indexesが有効な場合、log_throttle_queries_not_using_indexes変数は、スロークエリーログに書き込み可能な分あたりのクエリー数を制限します。 値 0 (デフォルト) は「制限なし」を意味します。 詳細は、セクション5.4.5「スロークエリーログ」を参照してください。
動作検証
- 関係パラメータ操作
- SQL実行
- mysqldumpslow実行
mysqldumpslow春
環境
- Docker
- MySQL 8.0.33
- スロークエリー有効化済み
- ログはファイル出力
(root@localhost) [world_x] 8.0.33 > show variables like '%slow%'; +-----------------------------+--------------------------------+ | Variable_name | Value | +-----------------------------+--------------------------------+ | log_slow_admin_statements | OFF | | log_slow_extra | OFF | | log_slow_replica_statements | OFF | | log_slow_slave_statements | OFF | | slow_launch_time | 2 | | slow_query_log | ON | | slow_query_log_file | /var/lib/mysql/sample-slow.log | +-----------------------------+--------------------------------+ 7 rows in set (0.00 sec)
使うサンプルテーブル
公式のサンプルデータベースをインポート済みです。
あと、行数が少なかったので15000行になるぐらいまで増やしました。
(root@localhost) [world_x] 8.0.33 > show tables; +-------------------+ | Tables_in_world_x | +-------------------+ | city | | country | | countryinfo | | countrylanguage | +-------------------+ 4 rows in set (0.00 sec) (root@localhost) [world_x] 8.0.33 > show create table city; +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | city | CREATE TABLE `city` ( `ID` int NOT NULL AUTO_INCREMENT, `Name` char(35) NOT NULL DEFAULT '', `CountryCode` char(3) NOT NULL DEFAULT '', `District` char(20) NOT NULL DEFAULT '', `Info` json DEFAULT NULL, PRIMARY KEY (`ID`) ) ENGINE=InnoDB AUTO_INCREMENT=4080 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci | +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec) (root@localhost) [world_x] 8.0.33 > show index from city; +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+ | Table | Non_unique | Key_name | Seq_in_index | Column_name | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | Visible | Expression | +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+ | city | 0 | PRIMARY | 1 | ID | A | 16335 | NULL | NULL | | BTREE | | | YES | NULL | +-------+------------+----------+--------------+-------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+ 1 row in set (0.01 sec)
比較順序
1. クエリーは管理ステートメントでないか、log_slow_admin_statements が有効になっている必要がある。
CREATE句でも記録されると思ってましたが、改めて説明読むと特定のものだけみたいですね。
set global log_slow_admin_statements = 1; (root@localhost) [world_x] 8.0.33 > set global log_slow_admin_statements = 1; Query OK, 0 rows affected (0.00 sec) (root@localhost) [world_x] 8.0.33 > select @@log_slow_admin_statements; +-----------------------------+ | @@log_slow_admin_statements | +-----------------------------+ | 1 | +-----------------------------+ 1 row in set (0.01 sec)
適当にテーブルにカラムを追加します。
ALTER TABLE test2 ADD test2 varchar(64);
mysqldumpslowでみてみると記録されてます。
値を無効化するとこのSQLは記録されないです。
root@b213e2466d85:/var/lib/mysql# mysqldumpslow sample-slow.log |grep ALTER Reading mysql slow query log from sample-slow.log ALTER TABLE test2 ADD test2 varchar(N)
2. クエリーに少なくとも long_query_time 秒かかっているか、log_queries_not_using_indexes が有効であって、クエリーは行参照にインデックスを使用していない。
大きく2つに分けて検証しますが、長いのでまとめ。
- long_query_timeで検知される場合
- log_queries_not_using_indexesで検知される場合
| クエリ | long_query_time(秒) | log_queries_not_using_indexes | 結果 |
|---|---|---|---|
| 実行時間0.1秒＆INDEXを使わない | 1 | 0(無効) | スロークエリーに記録されない |
| 実行時間0.1秒＆INDEXを使わない | 1 | 1(有効) | スロークエリーに記録される |
| 実行時間1秒＆INDEXを使わない | 0.1 | 0(無効) | スロークエリーに記録される |
| 実行時間1秒＆INDEXを使わない | 0.1 | 1(有効) | スロークエリーに記録される |
long_query_timeで検知される場合
INDEXを使うが実行時間がlong_query_timeを超えている。
set session long_query_time = 0.001; set global log_queries_not_using_indexes = 0; select * from city where id > 1000; root@b213e2466d85:/var/lib/mysql# mysqldumpslow sample-slow.log | grep select Reading mysql slow query log from sample-slow.log select * from city where id > N
INDEXを使わないが実行時間がlong_query_timeを超えている。
set session long_query_time = 0.001; set global log_queries_not_using_indexes = 0; (root@localhost) [world_x] 8.0.33 > select * from city where Name like '%d%' limit 10; +----+-----------+-------------+---------------+------------------------+ | ID | Name | CountryCode | District | Info | +----+-----------+-------------+---------------+------------------------+ | 2 | Qandahar | AFG | Qandahar | {"Population": 237500} | | 5 | Amsterdam | NLD | Noord-Holland | {"Population": 731200} | | 6 | Rotterdam | NLD | Zuid-Holland | {"Population": 593321} | | 9 | Eindhoven | NLD | Noord-Brabant | {"Population": 201843} | | 12 | Breda | NLD | Noord-Brabant | {"Population": 160398} | | 13 | Apeldoorn | NLD | Gelderland | {"Population": 153491} | | 15 | Enschede | NLD | Overijssel | {"Population": 149544} | | 19 | Zaanstad | NLD | Noord-Holland | {"Population": 135621} | | 23 | Dordrecht | NLD | Zuid-Holland | {"Population": 119811} | | 24 | Leiden | NLD | Zuid-Holland | {"Population": 117196} | +----+-----------+-------------+---------------+------------------------+ 10 rows in set (0.00 sec)
必要箇所抜粋
root@b213e2466d85:/var/lib/mysql# mysqldumpslow sample-slow.log Count: 1 Time=0.00s (0s) Lock=0.00s (0s) Rows=10.0 (20), root[root]@localhost select * from city where Name like 'S' limit N
log_queries_not_using_indexesで検知される場合
なにしても問答無用で検知される。
set session long_query_time = 1; set global log_queries_not_using_indexes = 1; (root@localhost) [world_x] 8.0.33 > select * from city where Name like '%d%' limit 10; +----+-----------+-------------+---------------+------------------------+ | ID | Name | CountryCode | District | Info | +----+-----------+-------------+---------------+------------------------+ | 2 | Qandahar | AFG | Qandahar | {"Population": 237500} | | 5 | Amsterdam | NLD | Noord-Holland | {"Population": 731200} | | 6 | Rotterdam | NLD | Zuid-Holland | {"Population": 593321} | | 9 | Eindhoven | NLD | Noord-Brabant | {"Population": 201843} | | 12 | Breda | NLD | Noord-Brabant | {"Population": 160398} | | 13 | Apeldoorn | NLD | Gelderland | {"Population": 153491} | | 15 | Enschede | NLD | Overijssel | {"Population": 149544} | | 19 | Zaanstad | NLD | Noord-Holland | {"Population": 135621} | | 23 | Dordrecht | NLD | Zuid-Holland | {"Population": 119811} | | 24 | Leiden | NLD | Zuid-Holland | {"Population": 117196} | +----+-----------+-------------+---------------+------------------------+ 10 rows in set (0.00 sec) root@b213e2466d85:/var/lib/mysql# mysqldumpslow sample-slow.log Count: 2 Time=0.00s (0s) Lock=0.00s (0s) Rows=10.0 (20), root[root]@localhost select * from city where Name like 'S' limit N
3. クエリーは少なくとも min_examined_row_limit 行を検査している必要がある。
min_examined_row_limitが超えていない場合。
long_query_timeを超えても記録されない。
set session long_query_time = 0.001; set global log_queries_not_using_indexes = 0; set session min_examined_row_limit =100000; (root@localhost) [world_x] 8.0.33 > select * from city where District = "Zuid-Holland" or CountryCode like '%a%'; +-------+--------------------------------+-------------+-----------------------+-------------------------+ | ID | Name | CountryCode | District | Info | +-------+--------------------------------+-------------+-----------------------+-------------------------+ | 1 | Kabul | AFG | Kabol | {"Population": 1780000} | | 2 | Qandahar | AFG | Qandahar | {"Population": 237500} | | 3 | Herat | AFG | Herat | {"Population": 186800} | | 4 | Mazar-e-Sharif | AFG | Balkh | {"Population": 127800} | | 34064 | Odessa | USA | Texas | {"Population": 89293} | | 34065 | Carson | USA | California | {"Population": 89089} | | 34066 | Charleston | USA | South Carolina | {"Population": 89063} | +-------+--------------------------------+-------------+-----------------------+-------------------------+ 4404 rows in set (0.01 sec)
min_examined_row_limitが超えている場合。
set session long_query_time = 0.001; set global log_queries_not_using_indexes = 0; set session min_examined_row_limit =4000; (root@localhost) [world_x] 8.0.33 > select * from city where District = "Zuid-Holland" or CountryCode like '%a%'; +-------+--------------------------------+-------------+-----------------------+-------------------------+ | ID | Name | CountryCode | District | Info | +-------+--------------------------------+-------------+-----------------------+-------------------------+ | 1 | Kabul | AFG | Kabol | {"Population": 1780000} | | 2 | Qandahar | AFG | Qandahar | {"Population": 237500} | | 3 | Herat | AFG | Herat | {"Population": 186800} | | 4 | Mazar-e-Sharif | AFG | Balkh | {"Population": 127800} | | 34064 | Odessa | USA | Texas | {"Population": 89293} | | 34065 | Carson | USA | California | {"Population": 89089} | | 34066 | Charleston | USA | South Carolina | {"Population": 89063} | +-------+--------------------------------+-------------+-----------------------+-------------------------+ 4404 rows in set (0.01 sec)
記録されている。
Count: 2 Time=0.01s (0s) Lock=0.00s (0s) Rows=4404.0 (8808), root[root]@localhost select * from city where District = "S" or CountryCode like 'S'
クエリーは、
log_throttle_queries_not_using_indexes設定によって抑制されていてはならない。
log_queries_not_using_indexesが有効になってないと抑制されない。
設定した値(分)の間に記録される件数が抑制される。
set global log_throttle_queries_not_using_indexes = 1; set global log_queries_not_using_indexes = 1; select * from city where info->"$.Population" > 10000 limit 10 ;
普通に記録される。
Count: 1 Time=0.02s (0s) Lock=0.00s (0s) Rows=16148.0 (16148), root[root]@localhost select * from city where info->"S" >
これを、log_throttle_queries_not_using_indexes有効化したあといっぱいSQL実行しても件数が増えない。
はじめ、log_queries_not_using_indexesを有効化してなかったのでいっぱい記録された。
Count: 14 Time=0.02s (0s) Lock=0.00s (0s) Rows=16148.0 (226072), root[root]@localhost select * from city where info->"S" > N
まとめ
- スロークエリーなら一定時間を上回るものは全部記録されると思ったがそうではない場合もある
- INDEXを使っていないクエリを取得したい場合は
long_query_timeを長くしてlog_queries_not_using_indexesを有効化すると良い log_queries_not_using_indexesを無効化してもlong_query_timeを超えていればスロークエリー判定になる- 多すぎるクエリは
log_throttle_queries_not_using_indexesで抑制できる
〆
DockerでイメージをOracle Linux OS使っててmysqldumpslowがどう頑張ってもできなかったのでDebianにした。
参考情報
MySQL :: MySQL 8.0 リファレンスマニュアル :: 4.6.9 mysqldumpslow — スロークエリーログファイルの要約
