log_slow_extraパラメータが8.0.14から追加された
何それ？おいしいの？
スロークエリーログが有効で出力先が含まれているFILE場合、サーバーはスローファイルに関する情報を提供するログファイル行に追加のフィールドを書き込みます。セクション5.4.5「遅いクエリーログ」を参照してください。 TABLE出力は影響を受けません。
https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_log_slow_extra
要するにファイル形式のスロークエリの場合、ログを詳細に出力するようになったよ、ってことらしい。 でもこれだと何が出力されるようになったのかわからん。
試してみる
スロークエリを出すように変更
mysql> set global slow_query_log_file = '/var/lib/mysql/slow_query.log'; Query OK, 0 rows affected (0.00 sec) mysql> set global slow_query_log = ON; Query OK, 0 rows affected (0.00 sec) mysql> SHOW GLOBAL VARIABLES LIKE '%slow_query%' ; +---------------------+-------------------------------+ | Variable_name | Value | +---------------------+-------------------------------+ | slow_query_log | ON | | slow_query_log_file | /var/lib/mysql/slow_query.log | +---------------------+-------------------------------+ 2 rows in set (0.00 sec)
細かいのがあんまり出てもうっとおしいのでlong_query_time を20秒に
mysql> SET GLOBAL long_query_time = 20.0 ; Query OK, 0 rows affected (0.00 sec)
log_slow_extraのデフォルト値はOFF
mysql> SHOW GLOBAL VARIABLES LIKE '%log_slow_extra%' ; +----------------+-------+ | Variable_name | Value | +----------------+-------+ | log_slow_extra | OFF | +----------------+-------+ 1 row in set (0.00 sec)
20秒越えのクエリ流す(log_slow_extra＝OFF時)
mysql> set session innodb_parallel_read_threads=10; Query OK, 0 rows affected (0.00 sec) mysql> select count(*) from xxx.table_size; +----------+ | count(*) | +----------+ | 10353209 | +----------+ 1 row in set (28.18 sec)
ちなみにinnodb_parallel_read_threadsも新パラメータであり、並列クラスター索引(PKとか)の読み取りに使用できるスレッド数を定義してパフォーマンスを向上させることができるものらすぃ。 (あんまり手元の環境だと効果見えないんだけど、効果出ているって報告もあるので後日検証する)
log_slow_extra=ONで再実行
mysql> SET GLOBAL log_slow_extra = ON ; Query OK, 0 rows affected (0.00 sec) mysql> SHOW GLOBAL VARIABLES LIKE '%log_slow_extra%' ; +----------------+-------+ | Variable_name | Value | +----------------+-------+ | log_slow_extra | ON | +----------------+-------+ 1 row in set (0.00 sec) mysql> select count(*) from xxx.table_size; +----------+ | count(*) | +----------+ | 10353209 | +----------+ 1 row in set (27.77 sec)
スロークエリ比較してみる
log_slow_extra＝OFF
# Time: 2019-01-23T01:47:49.810099Z # User@Host: root[root] @ [172.27.0.1] Id: 9947 # Query_time: 28.182507 Lock_time: 0.000141 Rows_sent: 1 Rows_examined: 0 SET timestamp=1548208041; select count(*) from xxx.table_size;
log_slow_extra＝ON
# Time: 2019-01-23T01:51:03.887338Z # User@Host: root[root] @ [172.27.0.1] Id: 9947 # Query_time: 27.771364 Lock_time: 0.000092 Rows_sent: 1 Rows_examined: 0 Thread_id: 9947 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 63 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 10353209 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2019-01-23T01:50:36.115974Z End: 2019-01-23T01:51:03.887338Z SET timestamp=1548208236; select count(*) from xxx.table_size;
差異(ONのほうにある項目)
| 項目名 | 値(上の値そのまま) |
|---|---|
| Thread_id | 9947 |
| Errno | 0 |
| Killed | 0 |
| Bytes_received | 0 |
| Bytes_sent | 63 |
| Read_first | 1 |
| Read_last | 0 |
| Read_key | 1 |
| Read_next | 10353209 |
| Read_prev | 0 |
| Read_rnd | 0 |
| Read_rnd_next | 0 |
| Sort_merge_passes | 0 |
| Sort_range_count | 0 |
| Sort_rows | 0 |
| Sort_scan_count | 0 |
| Created_tmp_disk_tables | 0 |
| Created_tmp_tables | 0 |
| Start | 2019-01-23T01:50:36.115974Z |
| End | 2019-01-23T01:51:03.887338Z |
だいぶ違うね。 Splunkとかに喰わせるとスロークエリのタイプを特定するのに使えそうな気がする。
