Zenn
レバテック開発部
🐢

スロークエリログをどう使えばいいのかって疑問、全て解決

もりた
2024/09/07に公開
2件
MySQL
監視
aurora
障害対応
tech

これはなに

ども、レバテック開発部のもりたです。

今回はMySQLでのスロークエリログについて調査してまとめました。
スロークエリログといえば古くからパフォーマンスチューニングの力強い味方といったふうに語られることも多いですが、最近はクラウドで使える便利なツールも生まれています。この記事ではスロークエリログの一般的な使い方を紹介するとともに、他のツールとの比較や、どんな場面でスロークエリログが役に立つのか、また役に立たない場合はどんなツールを利用することができるのかについてまとめました。
足りないところなどあればおおいにマサカリ投げていただけると幸いです。

記事の流れ

記事の流れ

この記事はそこそこ長いので、初めに記事の流れを解説します。適宜読み飛ばしてください。

  • なぜスロークエリログなのか
    • ここではそもそもスロークエリログをなぜ確認したいのかみたいなところを説明します
  • スロークエリログの使い方
    • スロークエリログを使う上での注意点や設定、あとはログの読み方を説明します
  • pt-query-digestのご紹介
    • スロークエリログの分析に使えるpt-query-digestをご紹介します。また、同様の役目を果たすツールとしてAWS RDS Performance Insightsや各種メトリクスのツールがありますが、それらとどう使い分けるべきかについても説明します
  • クイックスタート
    • 実際に使ってみる章です。スロークエリログを取得するのが地味に面倒くさいので、そこを簡単にするツールも紹介します。もりたがさっと作りました。

スロークエリログの使い方

Column: スロークエリログの意義

スロークエリログの使い方を説明する前に、そもそもなぜスロークエリログを使う必要があるのかについて整理しましょう。順を追って説明していきます。

  • Webシステムにおけるデータベースの重要性
    • Webエンジニアの大きな問題領域にはアプリケーションとデータベースがあると考えています。世の中にはいろんなシステムが存在しますが、大体のシステムにはアプリケーションとデータベースが存在し、どちらかに問題があるとユーザへの影響がでます。
    • もちろん他の構成物も存在しますが、このふたつが背負う部分は大きく、またエンジニアが手を加えやすいポイントでもあるため、障害の要因にもなりやすいです。
  • データベースにおけるパフォーマンス問題
    • ではさらにデータベースにスコープを絞って考えてみましょう。現代のデータベース（特にRDB）はクラウドで利用するケースが増えています。クラウド環境でのデータベースはフルマネージドで動くのが前提であり、そうなるとこれまでデータベースの問題領域だと思われていた問題のうち多くがクラウド側の問題になり、エンジニアが気にするべきものは絞られることになります。
    • その搾られた後に残っているのが「モニタリング/チューニング、スキーマ設計、クエリ作成」の三つです。そしてこれらの結果として問題になりやすいのが性能問題です
  • 性能問題とスロークエリログ
    • では、データベースの性能に問題が出るとはどういうことでしょうか？　それは大きく二つに分けられ、「SQL実行が多い/クエリが重たい」ことです。
    • そのうちの一つである重たいクエリが記録されるログが、このスロークエリログなわけですね
    • さらには後述の統計ツールを使うことでスロークエリログはより強力になります

スロークエリログの有効化

まず、ログの有効化について書きます。ログの出力方法はいろいろとありますが、ここではAWS CloudWatch Logsに出力させる想定で記載します。

基本的な有効化の方法として、以下の設定を有効化します。

  • slow_query_log
    • 1で有効
  • log_query_time
    • 任意の秒数。デフォルトは10秒で、システムに求められる非機能要件から適当な長さを設定してください
  • log_output
    • FILEとTABLE が選択可能。今回はログに出すのでデフォルトのFILEです

さらにRDSのクラスター設定画面でエクスポートしたいログとしてスロークエリをチェックします。


追加設定のところにあります

参考:
https://dev.classmethod.jp/articles/amazon-aurora-export-cloudwatch-logs/

またこの際に以下の設定についてもご確認ください。

スロークエリログの構成・読み方

では実際にスロークエリログの一例を使って、出力されたログを読んでみましょう。(log_slow_extraを有効化していない例です)

# Time: 2024-08-21T15:08:13.793503Z
# User@Host: samplesystem[samplesystem] @  [127.0.0.1]  Id: 84250948
# Query_time: 0.520603  Lock_time: 0.000147 Rows_sent: 100  Rows_examined: 227792
SET timestamp=1724252893;
select * from `sample_tables` where `sample_status` = 20 and `created_at` < '2024-08-22 00:08:11';

ログの構成はシンプルで、コメントとしてメタ情報が載り、最後にクエリ本体が記載されます。

気にしたいのは三行目に入る様々な実行時の情報だと思うため、そちらを以下に解説します。ここではlog_slow_extra で追記される情報も記します。

項目名 解説 備考、チューニング情報
以下は基本情報
Query_time クエリの実行時間
Lock_time ロックを取得する時間 8.0.27以前はスロークエリログに出力するクエリは「(Query_time - Lock_time) > long_query_time」の条件だったらしい。https://blog.s-style.co.jp/2023/03/9768/
Rows_sent クエリでヒットしたレコード数 ここが不必要に大きな場合は絞り込みたい
Rows_examined クエリで探索対象となったレコード数 インデックスが貼られてないとかだとここが多くなる
以下はextraの情報
Thread_id SHOW PROCESSLISTのID # User@Host: samplesystem[samplesystem] @ [127.0.0.1] Id: 84250948 で表示されるIdと同じ
Errno エラー番号。エラーでないなら0
Killed 終了の理由を示すエラー番号。killされてないなら0
Bytes_received MySQL サーバーがクライアントから受け取ったデータの総バイト数。クエリのデータや通信時のデータなどを含む。 SHOW STATUSで見れる内容と同じ。参考：https://dev.mysql.com/doc/refman/8.0/ja/server-status-variables.html
Bytes_sent MySQL サーバーがクライアントに送ったデータの総バイト数。クエリの結果セットや通信時のデータを含む。
Read_XX系 どのようにレコードにアクセスしたのかが表現されている。SHOW STATUSした際にHandler_read_xx として出てくるものと一緒。 次のページがめちゃくちゃ勉強になったのでおすすめ。Handler_read_* を理解する - hiboma
Read_first インデックスの最初のノードにアクセスした回数（ひとつのクエリでは基本的に最大１のはず。。）。ここがカウントされるのはインデックスの先頭を取得したケースだが、注意したいのはフルインデックススキャンになっていないかという点。Explainしてtype=indexとなっていたら注意 左の説明だとピンとこないと思う。とにかくこのページが良いのでぜひ見てほしい。Handler_read_* を理解する - hiboma
Read_last Read_firstとは逆にインデックスの最後のノードにアクセスした回数。降順にOrderByをつけると起きる。
Read_key インデックスを使ってレコードを特定した際にカウントされる数。type=rangeだと起点のレコードだけカウントされて、以降はRead_next(prev)でカウントされる。 とにかくこのページをだな…Handler_read_* を理解する - hiboma
Read_next 昇順のrange scanで順繰りにインデックスを読んでいく時にカウントされる。
Read_prev 降順のrange scanで順繰りにインデックスを読んでいく時にカウントされる。
Read_rnd ランダムにレコードを取得した際に最初に記録されるっぽい。。 だいぶ古いがこのページなどが参考になりそう。percona（後述）のブログです。https://www.percona.com/blog/what-does-handler_read_rnd-mean/
Read_rnd_next テーブルスキャンでread_next的にレコードを読むとカウントされる
Sort_merge_passes これがカウントされている場合はソート処理がメモリ上で完結せず、ファイルソートが行われている。メモリサイズを上げる対応が可能。
Sort_range_count 範囲指定でソートを行った回数 この「ソートを行った回数」がなにを指しているのか不明。ソート対象のレコード数？　そうっぽい
Sort_rows ソートされた行の数
Sort_scan_count 全件スキャンでのソート行数
Created_tmp_disk_tables クエリ実行中に作成されたディスク上の一時テーブル数 このページなどを参照。https://mita2db.hateblo.jp/entry/2022/05/14/150127
Created_tmp_tables 一時テーブルが作成された数。どこで作成されたかは関係ない
Start 開始時間
End 終了時間

pt-query-digestのご紹介と比較

ここまででスロークエリログの設定方法と読み方を解説しました。ここでは、そのスロークエリログをより効果的に使うためのツールとしてpt-query-digestをご紹介します。

ご紹介

pt-query-digest は、MySQL 向けのコマンドラインツールである Percona Toolkit の一機能です。この機能はスロークエリログをサマライズし、統計的に分析することができます。

データベースのスロークエリは特定のクエリだけを見ていても調査すべきか分からないことがあります。例えばそこまでの負荷でないクエリがあったとして、別のタイミングで発行された際は高負荷になっていることはままあります。逆にものすごい高負荷のクエリがあっても、高負荷になるのは年に一度深夜のバッチ処理で使うケースのみかもしれません。つまり全てのクエリを見る必要があるわけですが、人力で全てを見るのは不可能で、そういう際にこうやってサマリを出してくれるツールが嬉しいのです。pt-query-digest を使うことで、一定期間のログを収集し、そのデータを解析することで、スロークエリの全体的な統計情報を得ることができます。

スロークエリの改善は、問題が発生してから対応するのではなく、定期的にダイジェストを取得してデータを観測し、改善策を講じるのが望ましいです。気になるタイミングで調べるのも有効ですが、定期的な定点観測を行うことで、パフォーマンスのトレンドや潜在的な問題を早期に発見し、効果的な改善が可能になります。

使い方

ご自身の環境に合わせてググっていただければ使い方はわかります。とりあえずここではHomebrewでのインストール方法をお伝えします。

こうです。

brew install percona-toolkit

参考: percona-toolkit - Homebrew Formulae

使い方も簡単。コマンドラインで以下を実行します。
ここでは結果をログに出しています。

pt-query-digest path/to/slowquery-log > digest/slow-summary.log

参考: pt-query-digest[1]

結果ファイルの構成と読み方

先ほどのコマンドを実行すると、以下のようなテキストファイルが出力されます。

# 150ms user time, 20ms system time, 38.78M rss, 391.58G vsz
# Current date: Thu Aug 22 09:52:27 2024
# Hostname: mac
# Files: slowquery-log/raw-2024-08-08T14:30:00Z.log
# Overall: 89 total, 31 unique, 0.08 QPS, 0.44x concurrency ______________
# Time range: 2024-08-08T14:30:06 to 2024-08-08T14:47:40
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           468s   504ms     28s      5s     26s      8s   837ms
# Lock time           24ms    65us     4ms   267us   332us   410us   214us
# Rows sent        220.60k       1  20.04k   2.48k  13.13k   4.67k  964.41
# Rows examine      84.56M  59.45k   5.02M 972.92k   4.93M   1.42M 222.42k
# Query size       850.04k     400 188.28k   9.55k   7.68k  26.45k   5.73k

# Profile
# Rank Query ID                            Response time Calls R/Call  V/M
# ==== =================================== ============= ===== ======= ===
#    1 0x98516353194D1327969367400B39BEA4  93.7853 20.0%     6 15.6309  0.08 SELECT table_1 table_2
#    2 0x917FD79B8D4A941ED0AAA3B72A051DE4  53.1711 11.4%     3 17.7237  0.43 SELECT [...]
#    3 0x0A72475D5F6A5C2E182D87212243FDBB  35.3667  7.6%    35  1.0105  0.51 SELECT [...]
#    4 [...]
# MISC 0xMISC                              21.7467  4.6%    23  0.9455   0.0 <15 ITEMS>

# Query 1: 0.05 QPS, 0.84x concurrency, ID 0x98516353194D1327969367400B39BEA4 at byte 854198
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.08
# Time range: 2024-08-08T14:44:02 to 2024-08-08T14:45:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       6
# Exec time     20     94s     14s     17s     16s     16s      1s     16s
# Lock time      3   800us   114us   160us   133us   159us    14us   125us
# Rows sent      0   1.18k     201     201     201     201       0     201
# Rows examine  35  30.15M   5.02M   5.02M   5.02M   4.93M       0   4.93M
# Query size     2  22.30k   3.72k   3.72k   3.72k   3.72k       0   3.72k
# String:
# Databases    sample
# Hosts        172.0.0.1 (5/83%), 172.0.0.2 (1/16%)
# Users        samplesystem
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `samplesystem` LIKE 'tbl_1'\G
#    SHOW CREATE TABLE `samplesystem`.`tbl_1`\G
#    SHOW TABLE STATUS FROM `samplesystem` LIKE 'tbl_2'\G
#    SHOW CREATE TABLE `samplesystem`.`tbl_2`\G
#    [...]
# EXPLAIN /*!50100 PARTITIONS*/
select `table_1`.`id` as `table_1_id`,[...]

長っっと思ったあなた、実物はもっと長いです。でもご安心ください、構造を知るととてもシンプルです。
pt-query-digestの出力は以下のものでできています。

  • 全体の統計情報
  • ランキング
  • 個別のクエリについての統計情報

以下にひとつずつ説明します。

全体の統計情報

# 150ms user time, 20ms system time, 38.78M rss, 391.58G vsz
# Current date: Thu Aug 22 09:52:27 2024
# Hostname: mac
# Files: slowquery-log/raw-2024-08-08T14:30:00Z.log
# Overall: 89 total, 31 unique, 0.08 QPS, 0.44x concurrency ______________
# Time range: 2024-08-08T14:30:06 to 2024-08-08T14:47:40
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           468s   504ms     28s      5s     26s      8s   837ms
# Lock time           24ms    65us     4ms   267us   332us   410us   214us
# Rows sent        220.60k       1  20.04k   2.48k  13.13k   4.67k  964.41
# Rows examine      84.56M  59.45k   5.02M 972.92k   4.93M   1.42M 222.42k
# Query size       850.04k     400 188.28k   9.55k   7.68k  26.45k   5.73k

この箇所が全体の統計情報になります。

分析対象クエリの件数や実行日時の情報のあとに、クエリの実行時間、対称行などの情報がマトリクスで表示されます。以下にこのマトリクスの行について説明します。

  • Exec time
    • クエリの実行にかかった時間
  • Lock time
    • クエリ実行に際してのロック待ち時間
  • Rows sent
    • クライアントに実際に返された行数
  • Rows examine
    • 走査された行数
    • たとえばインデックスなしのテーブルから一行取るだけだとテーブル全体の行数がここに入る
  • Query size
    • クエリ文字列の長さ

ランキング


# Profile
# Rank Query ID                            Response time Calls R/Call  V/M
# ==== =================================== ============= ===== ======= ===
#    1 0x98516353194D1327969367400B39BEA4  93.7853 20.0%     6 15.6309  0.08 SELECT table_1 table_2
#    2 0x917FD79B8D4A941ED0AAA3B72A051DE4  53.1711 11.4%     3 17.7237  0.43 SELECT [...]
#    3 0x0A72475D5F6A5C2E182D87212243FDBB  35.3667  7.6%    35  1.0105  0.51 SELECT [...]
#    4 [...]
# MISC 0xMISC                              21.7467  4.6%    23  0.9455   0.0 <15 ITEMS>

見ての通りランキングです。実際は15位くらいまで表示されます。

個別のクエリについての統計情報


# Query 1: 0.05 QPS, 0.84x concurrency, ID 0x98516353194D1327969367400B39BEA4 at byte 854198
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.08
# Time range: 2024-08-08T14:44:02 to 2024-08-08T14:45:54
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          6       6
# Exec time     20     94s     14s     17s     16s     16s      1s     16s
# Lock time      3   800us   114us   160us   133us   159us    14us   125us
# Rows sent      0   1.18k     201     201     201     201       0     201
# Rows examine  35  30.15M   5.02M   5.02M   5.02M   4.93M       0   4.93M
# Query size     2  22.30k   3.72k   3.72k   3.72k   3.72k       0   3.72k
# String:
# Databases    sample
# Hosts        172.0.0.1 (5/83%), 172.0.0.2 (1/16%)
# Users        samplesystem
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS FROM `samplesystem` LIKE 'tbl_1'\G
#    SHOW CREATE TABLE `samplesystem`.`tbl_1`\G
#    SHOW TABLE STATUS FROM `samplesystem` LIKE 'tbl_2'\G
#    SHOW CREATE TABLE `samplesystem`.`tbl_2`\G
#    [...]
# EXPLAIN /*!50100 PARTITIONS*/
select `table_1`.`id` as `table_1_id`,[...]

ここでは再び実行時情報のマトリクスと、加えてクエリ実行時間の分布や関連するテーブル情報が表示されます。また最後に具体的な値をマスキング？？？したやつもでています。

また、上記は追加情報のない状態であり、またpt-query-digestには実際に使う上で便利なオプション等もありますので、使う際はそこらへんも調べた上で使うとHappyになれるかと思います。

活かし方

この統計情報をもとにクエリの改善に役立てるわけですが、代表的な見立ての立て方を以下に引用します。

「筆者はここで Rows examine / Rows sent の値をよく計算します。GROUP BYを使っている場合を除けばRows examine / Rows sentの値が1に近い（小さい）ほど効率良くインデックスで WHERE 句を処理できているからです。1に近いほどインデックス以外の箇所でSQLをチューニングしなければならないため時間がかかり、1から遠いほどインデックスの追加で劇的に速くなる可能性があるため、効率良くチューニングできる可能性が高まります。」

「またRows sentやRows examine、Exec timeに大きなバラつきがあり相関しているように見える場合、WHERE句の条件によって結果セットの大きさが大幅に変化していることが考えられます。転送された結果セットが本当に全てアプリケーション側で利用されているかを確認すると良いでしょう（本当に使われていた場合はどうしようもないが）。」

「Rows sent、Rows examine、Lock timeにバラつきが少ないにも関わらずExec timeにバラつきがある場合は、バッファプールのヒット率が悪いことなどが考えられます（MyISAMストレージエンジンのテーブルであればこの限りではない）。InnoDBバッファプールはSELECTのみでなくINSERTやDELETEの際にも利用されます。またInnoDBのテーブル圧縮を使用している場合、バッファプールミスヒットのコストは無圧縮状態に比べて非常に高くなるため注意が必要です。バッファプールの他にもテーブルキャッシュが足りなくなっていないかなども考慮する必要があります。

（引用元：スローログの集計に便利な「pt-query-digest」を使ってみよう - Think IT）

競合ツールとの比較

  • 紹介の最後に、pt-query-digestと類似のツールとの比較をします。どんな立ち位置なのかを整理するためです
  • 比較するのはこちら
    • AWS RDS Performance Insights
    • CloudWatch
    • Datadog
    • Anemometer
    • mysqldumpslow
  • 適当なマトリクスを置いてますがあくまでデータベースの調査観点でとご理解ください
ツール 習得の容易さ 使いやすさ 分析能力 カスタマイズ性 金銭コスト クラウドツール
pt-query-digest △ △ ◯ ◯ ◯ No
AWS RDS Performance Insights ◯ ◯ ◯ △ △ Yes
CloudWatch △ ◯ △ △ △ Yes
Datadog △ ◯ ◯ △ × Yes
Anemometer △ ◯ △ △ ◯ No
mysqldumpslow ◯ △ △ × ◯ No

ツールごとの使用目的と寸評（データベースの調査観点）

  1. pt-query-digest
    • 使用目的
      • MySQLのスロークエリログを解析し、パフォーマンスのボトルネックを特定する
    • 寸評
      • 高度な分析が可能でカスタマイズ性も高い。習得には多少時間がかかるが、コストは無料でデータベース調査に向いている。またローカルで使うツールなのでDB本体に負荷をかけることなく調査できるのも障害対応時には嬉しいところ
  2. AWS RDS Performance Insights
  3. CloudWatch
    • 使用目的
      • AWSリソースとアプリケーションのパフォーマンスメトリクスを収集し、可視化してデータベースの問題を把握する
    • 寸評
      • クラウドベースの定番ツールだが検知が主目的。クエリの分析目的では使用しない
  4. Datadog
    • 使用目的
      • インフラストラクチャとアプリケーションの監視を通じてデータベースのパフォーマンスを包括的に調査する
    • 寸評
      • 高度な機能と使いやすさ。ただしこちらも監視目的。あとコストが高いのが難点
  5. Anemometer
    • 使用目的
      • MySQLのスロークエリログを解析し、パフォーマンス問題を視覚的に理解する。
    • 寸評
      • 無料ツールかつ視覚的に捉えることが可能だが、最近メンテナンスされているか微妙。設定周りが面倒くさそうなので敬遠してます
  6. mysqldumpslow
    • 使用目的
      • MySQLのスロークエリログをテキストベースで分析し、パフォーマンスのボトルネックを特定する
    • 寸評
      • シンプルかつMySQL公式だがpt-query-digestが優秀なのであまり日の目を見ない

クイックスタート

ではさっそく使ってみましょう。pt-query-digestを利用する上で多少面倒なのはローカルにスロークエリログを吐き出すことです。ただそこで躓いてしまうのももったいないので、以下のようなツールを作ってきました。

https://github.com/mconfjp/db-tools

percona-toolkitのインストールが前提ですが、それ以外はこのリポジトリでよしなにやります。使う側が行う作業としては、

  • .envの編集
    • ロググループ名を対象のスロークエリログに変更
    • AWSの認証情報を設定
    • 取得する時間帯の指定
  • yarn node index.js
    • スロークエリログの取得
  • pt-query-digestの実行
    • 例）pt-query-digest ./slowquery-log/raw-2024-09-02.log > digest/slow-summary.log

おわりに

以上です！！
ちょっと長かったですが、スロークエリの予防や調査の場面で使えるようになれば幸いです。

...と言いつつも、次の一歩

スロークエリの予防や調査の場面で使えるようになれば幸いです。

と書きましたが、一方で、それ以外の点は分かりません。

例えば、重たいクエリの改善についてはExplainやPerformance schemaも利用した方が良いでしょう。また、ロックの情報だったりユーザーによるDBのダンプもスロークエリログには出てきません。そういった要因についてはエラーログ/監査ログだったり、他のツールを利用することも必要になります。

まだまだデータベースログの道は長いということで、そこらへんの情報についてもこれから調べてまとめたいと思いました（感想）。

参考文献

脚注

  1. 全く関係ないんですがperconaのブログは良い記事が多いのでおすすめです。先日もクエリパフォーマンス決定版みたいな記事をあげてました。
    ↩︎

レバテック開発部
レバテック開発部

レバテック開発部の公式テックブログです！

Discussion