第154回　スロークエリログに出力される項目とlog_slow_extra

本連載ではこれまでスロークエリログについて、いくつか紹介してきました。

これらの記事では、スロークエリログを出力する方法であったり、スロークエリログの可視化やツールを使っての解析などを紹介しています。今回は、MySQL 8.0から追加されたスロークエリログの出力項目の拡張機能（log_slow_extra）や出力される項目について紹介したいと思います。

スロークエリログを出力するための設定方法や、それらのオプションについての説明は省きますので、上記の記事を先に目を通していただけると、より理解は深まると思います。使用しているMySQLのバージョンはMySQL 8.0.26です。

MySQL 5.7までのスロークエリログに出力される項目

まずは、とあるスロークエリログの1つの中身を見てみます。

# Time: 2021-08-29T08:49:05.382813Z
# User@Host: root[root] @  [172.17.0.1]  Id:    10
# Query_time: 9.685363  Lock_time: 0.000210 Rows_sent: 1  Rows_examined: 2097153
SET timestamp=1630226935;
SELECT * FROM test WHERE col1=10;

スロークエリログを頻繁に確認する人はよくご存知かと思いますが、このような表示が確認できます。この項目について簡単に説明したいと思います。

Time …スロークエリログに書き込んだ時間
User@Host …クエリを実行したユーザアカウント
Id …SHOW PROCESSLISTのID
Query_time …ステートメントの実行時間（秒）
Lock_time …ロックを取得した時間（秒）
Rows_sent …クライアントに送信された行数
Rows_examined …MySQLが内部で走査した行数

これらの項目からよくチューニングするポイントとしては、Rows_examinedとRows_sentを比較することです。この2つの差が大きい場合はインデックスが存在しない（このケースはcol1にインデックスがない）などでフルスキャンが発生し、クエリの実行が遅くなっていることが確認できます。2097153行（Rows_examined）の走査に対して、結果セットは1行（Rows_sent）となっています。MySQL 5.7までは、これらの項目のみしか表示しませんでした。

MySQL8.0からスロークエリログに出力される項目

MySQL 8.0からスロークエリログの出力項目を増やすlow_slow_extraオプションが追加されました。デフォルトはOFFのため、使用するにはONに変更する必要があります。オンラインでの変更が可能です。low_slow_extraオプションをONにした結果が以下になります。

# Time: 2021-08-29T08:50:58.916765Z
# User@Host: root[root] @  [172.17.0.1]  Id:    10
# Query_time: 9.076753  Lock_time: 0.000243 Rows_sent: 1  Rows_examined: 2097153 Thread_id: 10 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 251 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 2097154 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: 2021-08-29T08:50:49.840012Z End: 2021-08-29T08:50:58.916765Z
SET timestamp=1630227049;
SELECT * FROM test WHERE col1=10;

このようにかなり項目が増えました。それぞれ簡単に説明します。

Thread_id …Idと同じくSHOW PROCESSLISTのID
Errno …エラー番号、エラーが発生しなかった場合は0
Killed …終了した場合、理由を示すエラー番号。ステートメントが正常に終了した場合は0
Bytes_received …ステートメントのステータスBytes_receivedの値
Bytes_sent … ステートメントのステータスBytes_sentの値
Read_xx …ステートメントのステータス Handler_Read_xxのそれぞれの項目の値
Sort_merge_passes …ステートメントのステータスSort_merge_passesの値
Sort_range_count …ステートメントのステータスSort_range_countの値
Sort_rows …ステートメントのステータスSort_rowsの値
Sort_scan_count …ステートメントのステータスSort_scan_countの値
Created_tmp_disk_tables …ステートメントのステータスCreated_tmp_disk_tablesの値
Created_tmp_tables …ステートメントのステータスCreated_tmp_tablesの値
Start …ステートメントの実行開始時間
End …ステートメントの実行終了時間

ステートメントのステータスというのは、SHOW STATUSで表示される項目と同様です。いくつかの項目をもとに、クエリチューニングのアプローチ方法を紹介したいと思います。

Sortの項目

ソートの項目から値が0ではない場合は、そのクエリはソート処理が実行されていることがわかります。特にSort_merge_passesの値は注意です。この値はsort_buffer_sizeサイズを超えてファイル（ディスク）を使用したマージパス回数です。この値が大きいと、クエリは遅くなるでしょう。sort_buffer_sizeサイズを大きくする、またはソート処理をしないようにクエリを書き換える、などのチューニングを行います。

また、Sort_rowsはソートした行数が表示されます。しかし、ORDER BY col1 LIMIT 50というクエリがあった場合、実際はすべての行をソートしたとしても、Sort_rowsの値はLIMITの値の50になります。そのため、Sort_rowsが少ないからソート処理しても問題ないだろうと考えるのではなく、Rows_examinedの値も一緒に確認すると良いでしょう。

Created_tmpの項目

この値は内部テンポラリーテーブルを作成した回数になります。

Created_tmp_tablesはインメモリテンポラリテーブルを作成した回数で、Created_tmp_disk_tablesはディスクテンポラリテーブルを作成した回数です。内部テンポラリテーブルについては、第129回　Internal Temporary Table（内部テンポラリテーブル）について［その1］と第132回　Internal Temporary Table（内部テンポラリテーブル）について［その2］をご確認ください。

Created_tmp_disk_tablesが0ではない場合は内部テンポラリテーブルが大きいと思われるので、内部テンポラリテーブルを作成しないクエリへの書き換えや、インメモリテンポラリテーブルのメモリサイズ（オプションは使用しているストレージエンジンよって異なる）を大きくするなどのチューニングができます。

Bytes_sentの項目

Bytes_sentは、筆者としてはとてもうれしい追加項目です。たとえば、MySQLサーバのネットワーク使用率が高いときに、どのクエリが一番ネットワーク帯域を消費しているか確認することに使えます。

今までは、流れてしまったクエリ（アプリケーションが実行したクエリ）のBytes_sentの値を外側から観測することはとても難しいことでした。このようなケースの場合は、log_slow_extraオプションを有効にして確認するとよいでしょう。

StartとEnd

従来のスロークエリログでは、Timeの項目にスロークエリログが書き込まれた時間を表示していました。実質、Endのクエリの終了時間と同様になります。

TimeからQuery_time時間を引いてクエリの実行開始時間を出していましたが、新たにStart項目が追加され、クエリの実行開始時間も表示されるようになりました。こちらもうれしい追加項目です。

まとめ

今回はスロークエリログの出力項目と、それらの活用方法について紹介しました。

ちなみに、スロークエリログを解析してくれるツールは、low_slow_extraオプションの追加項目に対応しているのでしょうか。確認したところ、pt-query-digestは対応されていますが、MySQL 8.0.26現在ではmysqldumpslowは対応していません。