🐢

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

もりた

2024/09/07に公開

 これはなにども、レバテック開発部のもりたです。
今回は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_queries_not_using_indexes:
1で有効化できます。 long_query_timeの値に満たないクエリでも、インデックスを使わない場合は出力されるようになります
参考：https://docs.aws.amazon.com/ja_jp/AmazonRDS/latest/AuroraUserGuide/USER_LogAccess.MySQL.LogFileSize.html
なおMySQL公式の解説だとこの設定項目の説明がめっちゃわかりにくくなっている



log_slow_extra
1を設定して有効化することで、スロークエリログで確認できる項目が増えます。面白いのでもりた的には推奨
参考：https://gihyo.jp/dev/serial/01/mysql-road-construction-news/0154


 スロークエリログの構成・読み方では実際にスロークエリログの一例を使って、出力されたログを読んでみましょう。(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


 ツールごとの使用目的と寸評（データベースの調査観点）
pt-query-digest
使用目的
MySQLのスロークエリログを解析し、パフォーマンスのボトルネックを特定する

寸評
高度な分析が可能でカスタマイズ性も高い。習得には多少時間がかかるが、コストは無料でデータベース調査に向いている。またローカルで使うツールなのでDB本体に負荷をかけることなく調査できるのも障害対応時には嬉しいところ



AWS RDS Performance Insights
使用目的
AWS RDSインスタンスのパフォーマンスを視覚的にモニタリングし、データベースのボトルネックを特定する

寸評
使いやすく分析能力も高い。AWSユーザがまず使うなら絶対これ。次の資料を読むと概要がわかります
Amazon RDS / Amazon Aurora パフォーマンスチューニングとモニタリング
Amazon RDS におけるパフォーマンス最適化とパフォーマンス管理 | AWS Summit Tokyo 2019

もりたも紹介の記事を書いているので読んでね
AWS RDS/Auroraでモニタリング＆チューニングを始めるための資料11選




CloudWatch
使用目的
AWSリソースとアプリケーションのパフォーマンスメトリクスを収集し、可視化してデータベースの問題を把握する

寸評
クラウドベースの定番ツールだが検知が主目的。クエリの分析目的では使用しない



Datadog
使用目的
インフラストラクチャとアプリケーションの監視を通じてデータベースのパフォーマンスを包括的に調査する

寸評
高度な機能と使いやすさ。ただしこちらも監視目的。あとコストが高いのが難点



Anemometer
使用目的
MySQLのスロークエリログを解析し、パフォーマンス問題を視覚的に理解する。

寸評
無料ツールかつ視覚的に捉えることが可能だが、最近メンテナンスされているか微妙。設定周りが面倒くさそうなので敬遠してます



mysqldumpslow
使用目的
MySQLのスロークエリログをテキストベースで分析し、パフォーマンスのボトルネックを特定する

寸評
シンプルかつMySQL公式だがpt-query-digestが優秀なのであまり日の目を見ない


!slpというツールがあり、それも便利みたいです。

https://github.com/tkuchiki/slp
コメントで教えていただいたinductorさん、ありがとうございます！！

 クイックスタートではさっそく使ってみましょう。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のダンプもスロークエリログには出てきません。そういった要因についてはエラーログ/監査ログだったり、他のツールを利用することも必要になります。
まだまだデータベースログの道は長いということで、そこらへんの情報についてもこれから調べてまとめたいと思いました（感想）。

 参考文献書籍
『MySQL運用・管理［実践］入門 〜安全かつ高速にデータを扱う内部構造・動作原理を学ぶ』

『MySQL即効クエリチューニング』
以下の動画で同じ内容を説明しています
MySQLer七つ道具【第十八回 中国地方DB勉強会 in 広島】



webの記事

-　【アップデート】Amazon Auroraでスロークエリや一般ログがCloudWatch Logsへ出力可能に

Aurora MySQL データベースログの概要
Auroraの公式ドキュメントは結構良い

スロークエリログ周り
5.4.5 スロークエリーログ - MySQL
スロークエリログに出力される項目とlog_slow_extra - MySQL道普請便り
スロークエリログの Lock_time と出力条件の仕様変更について

Handler_read_* を理解する
この記事25時くらいに見つけたんですがマジで目が覚めるような良記事でした

What does Handler_read_rnd mean?

最近の MySQL の Internal Temporary Table ステータスとチューニング観点まとめ (version 8.0.28 版)
tmpテーブル周り



スローログの集計に便利な「pt-query-digest」を使ってみよう
おそらくMySQL即効クエリチューニングとかぶっている内容。この連載を元に書籍は書かれているはず


ツール
percona-toolkit

db-tools
もりたが作成したツール



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

 ↩︎

項目名	解説	備考、チューニング情報
以下は基本情報
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	△	△	◯	◯	◯	No
AWS RDS Performance Insights	◯	◯	◯	△	△	Yes
CloudWatch	△	◯	△	△	△	Yes
Datadog	△	◯	◯	△	×	Yes
Anemometer	△	◯	△	△	◯	No
mysqldumpslow	◯	△	△	×	◯	No

レバテック開発部

レバテック開発部の公式テックブログです！レバテック開発部 Advent Calendar 2024 実施中: qiita.com/advent-calendar/2024/levtech

Discussion

inductor

https://github.com/tkuchiki/slp が便利です

もりた

へえ〜〜ありがとうございます！！！　全然知りませんでした。
更新できるタイミングで記事にも追加させていただきます！🙏