MySQL道普請便り

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

この記事を読むのに必要な時間:およそ 2 分

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

これらの記事では,スロークエリログを出力する方法であったり,スロークエリログの可視化やツールを使っての解析などを紹介しています。今回は,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_examinedRows_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_idIdと同じく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は対応していません。

著者プロフィール

北川健太郎(きたがわけんたろう)

LINE株式会社所属のデータベースエンジニア。担当はMySQLとOracle Database。好きなMySQLの機能はレプリケーションで,好きなOracleDatabaseの機能はログオントリガー。

Twitter:@keny_lala