📝 はじめに
自社で月間PV数1500～2000万以上のメディアサイトを運営しており、
私はそのメインエンジニアを担当させてもらっています。
日々、保守運用から新規開発のリードまでいろいろとやっていますが、なにをするにも可用性。パフォーマンス。
その対策のためにも、スロークエリ調査自体の効率化、最適化も大事だよなーーと思いつつ、自分なりにこれもまあアリかも、という方法を策定？したので、残しておきたいと思います。
ざっくりいうと、AWS CloudWatchからCSVデータをダウンロードし、Google ColabにてPythonで整形して、pt-query-digestツールで解析するまでの一連の流れですね。
そうすると、なにがオイシイのか。
Thanks for the reference! 👏
pt-query-digestとは？
pt-query-digestと出合わせてくれた下記記事で知ることができます。
🌟 必要なもの・想定環境
- Mac（Brewコマンドがインストールされている前提）
- AWSアカウント、およびCloudWatch権限
- Google Colab（Python実行できればなんでもOK）
📊 AWS CloudWatchからCSVダウンロード
CloudWatchのログのインサイトからCSVデータをエクスポートします。
※
CloudWatchのログのインサイトは、それ自体でも高度な分析機能を提供していますが、
特定の形式（pt-query-digest用）に変換するためには追加の処理が必要です。
そのためにダウンロードします。
- CloudWatchのログのインサイトに移動
- 分析したいロググループを選択
- 必要なフィルタ条件を設定（例：
fields @timestamp, @message, @log、あと期間指定も） - クエリを実行後、「CSVとしてダウンロード」を選択
awsコマンドでも直接、分析可能な形式でダウンロードすることもできますが、期間指定や件数がうまくいっていないため、一旦断念しています。
期間や件数、各クエリの内容を一旦確認してからダウンロードできるという点ではGUIのほうが良いという実感もありました。
💻 Pythonで整形する
最初はダウンロードしたCSVをそのままpt-query-digestに投げて分析できるか？とやってみたのですが
形式がマッチしていないようでエラーに。
今回はPythonで整形する方法を採用しました。
CSVはかなり大容量になるので、ちょこちょこ手で直すわけにもいかず
Google Colabを使って、CSVデータをpt-query-digestで解析可能な形式に変換します。
（まあ、やっていることとしては、pt-query-digest向けにダブルクォーテーションを消すくらいなんですけれど。。）
Pythonコード全文
# CSVファイルを処理してMySQLスロークエリログフォーマットに変換
import pandas as pd
import io
# CSVファイルを読み込み
df = pd.read_csv('logs-insights-results.csv')
# カラム名を確認
print("CSVファイルのカラム名:", df.columns.tolist())
# 最初の数行を表示して内容を確認
print("\nCSVファイルの最初の3行:")
print(df.head(3))
# @messageカラムの抽出とクリーニング
if '@message' in df.columns:
messages = df['@message'].str.replace('"', '')
# 出力を確認
print("\n処理後のメッセージの最初の3行:")
for i, msg in enumerate(messages.head(3)):
print(f"メッセージ {i+1}:\n{msg}\n")
# フォーマットされたログファイルを作成
with open('formatted_slowquery.log', 'w') as f:
for msg in messages:
f.write(f"{msg}\n")
# 処理されたファイルの行数をカウント
print(f"\n処理されたログの行数: {len(messages)}")
else:
print("\nエラー: '@message'カラムがCSVファイルに見つかりません")
print("CSVファイルの内容を確認してください")
# 最初の行を詳しく見る
if len(df) > 0:
print("\n最初の行の詳細:")
first_row = df.iloc[0]
for col in df.columns:
print(f"{col}: {first_row[col]}")
# ログのサンプル分析（基本的な統計情報）
print("\n基本的なログ分析:")
try:
# クエリ時間情報を抽出
query_times = []
for msg in messages:
if "Query_time:" in msg:
try:
query_time_str = msg.split("Query_time:")[1].split()[0]
query_times.append(float(query_time_str))
except:
pass
if query_times:
print(f"クエリ数: {len(query_times)}")
print(f"平均クエリ時間: {sum(query_times)/len(query_times):.4f} 秒")
print(f"最大クエリ時間: {max(query_times):.4f} 秒")
print(f"最小クエリ時間: {min(query_times):.4f} 秒")
else:
print("クエリ時間情報が見つかりませんでした")
except:
print("ログ分析中にエラーが発生しました")
# 最も重いクエリ上位3件のサンプルを表示
try:
queries_with_times = []
current_query_time = None
current_query = []
for msg in messages:
if "Query_time:" in msg:
if current_query_time is not None and current_query:
queries_with_times.append((current_query_time, ''.join(current_query)))
current_query = []
try:
current_query_time = float(msg.split("Query_time:")[1].split()[0])
except:
current_query_time = None
elif current_query_time is not None and not msg.startswith('#') and msg.strip():
current_query.append(msg)
# 最後のクエリを追加
if current_query_time is not None and current_query:
queries_with_times.append((current_query_time, ''.join(current_query)))
# クエリを実行時間で降順にソート
queries_with_times.sort(reverse=True)
if queries_with_times:
print("\n実行時間が最も長いクエリ上位3件:")
for i, (time, query) in enumerate(queries_with_times[:3]):
print(f"\n{i+1}. 実行時間: {time:.4f} 秒")
print(f"クエリ: {query[:200]}..." if len(query) > 200 else f"クエリ: {query}")
else:
print("\nクエリ情報が抽出できませんでした")
except:
print("\nクエリ情報の抽出中にエラーが発生しました")
# フォーマットされたファイルをダウンロードするためのリンクを生成
from google.colab import files
files.download('formatted_slowquery.log')
🔑 コードのポイント:
- CSVファイルを読み込み、構造を確認
-
messageカラムからダブルクォートを削除 - 整形したデータを
formatted_slowquery.logとして保存 - 簡単な統計分析も実施（クエリ時間の平均・中央値・最大値など）
以前の処理結果が残っている場合、以前のキャッシュが何らかの影響で古い情報が処理されるケースがあるかもしれません。そのため一度Colabをリロードし、古いlogs-insights-results.csvが存在する場合は事前に削除してから作業してください。
🛠 pt-query-digestでの分析実行
ローカルにformatted_slowquery.logがDLされているはずなので
それを使ってpt-query-digestツールで詳細な分析を行います。
ツール分析実行
事前にツールのインストールが必要。brewでの記載。
brew install percona-toolkit
そして分析を実行:
pt-query-digest formatted_slowquery.log > query_analysis_report.txt
📈 分析結果の確認
query_analysis_report.txtとして生成された実行結果のレポートを確認できます。
実際の分析結果の一部
pt-query-digestの分析結果例
※以下の情報をマスキングしています：
- データベース名：実際のデータベース名を一般的な名前（db_stg, db_prd）に置き換えました
- IPアドレス：すべてのIPアドレスを[IP-MASKED]に置き換えました
- ユーザー名：管理者アカウント名を[USER-MASKED]に置き換えました
- カテゴリID：すべてのカテゴリIDを[ID-MASKED]に置き換えました
全体サマリー
# 2s user time, 450ms system time, 198.77M rss, 33.70G vsz
# Current date: Sun May 4 16:15:12 2025
# Hostname: MacBook-Air.local
# Files: formatted_slowquery.log
# Overall: 407 total, 24 unique, 0.00 QPS, 0.00x concurrency _____________
# Time range: 2025-04-27T09:00:08 to 2025-05-04T06:14:00
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 2146s 3s 21s 5s 13s 3s 4s
# Lock time 12ms 1us 2ms 30us 10us 141us 1us
# Rows sent 2.32M 0 255.54k 5.83k 1.33k 33.35k 0.99
# Rows examine 28.64M 0 1.22M 72.06k 56.74k 156.02k 54.03k
# Query size 20.44M 37 4.07M 51.43k 511.45 424.17k 136.99
プロファイル（上位クエリ一覧）
# Profile
# Rank Query ID Response time Calls R/Call V
# ==== =================================== =============== ===== ======= =
# 1 0xF27CEE401A7A6E75977FE1A782B008D1 1026.6118 47.8% 227 4.5225 0.46 SELECT article
# 2 0x252F1C654E3B43B4E6AA5BAAE7621FC4 292.2512 13.6% 72 4.0590 0.20 SELECT article article_category
# 3 0xCF1F9CF01C1DFFC9611C49D77BB5341B 209.9613 9.8% 13 16.1509 0.36 SELECT article
# 4 0x6F3C64CAF7BED1768AC17512A4A7F633 155.0896 7.2% 31 5.0029 1.06 SELECT article_keyword article
# 5 0xFD4E637CB1FC76B1798E21C077FE5ADD 129.2817 6.0% 10 12.9282 0.34 DELETE article_analytics
# 6 0x36E2DBD38AFC2BA555E2287AC213930B 64.9852 3.0% 5 12.9970 0.14 INSERT SELECT article_analytics article_analytics_temporary
# 7 0xA164DF4D80587FBE4AA75AD85B314855 38.0741 1.8% 7 5.4392 0.06 SELECT newsletter_delivery_error_log
# 8 0xB11EF20A5386E8D46428DEB87DE7EE9B 37.8278 1.8% 6 6.3046 2.74 SELECT UNION member member_newsletter old_users
# 9 0xDE70B390F2829288A6E4E61E0F728B6E 33.9009 1.6% 7 4.8430 0.09 DELETE rss_revision
# 10 0x4F56A0A97A615CC63E812935E8F6C45E 23.6276 1.1% 6 3.9379 0.12 SELECT article author article_category
# 11 0x5F9DC03849C3EA8F1AEB190648F910BA 16.1986 0.8% 1 16.1986 0.00 INSERT SELECT article_analytics article_analytics_temporary
# 12 0xAF64BF1AE5C0E03A698D4EA777FC25B1 14.4758 0.7% 4 3.6190 0.05 SELECT config
# MISC 0xMISC 103.6006 4.8% 18 5.7556 0.0 <12 ITEMS>
クエリ #1 の詳細 (最も時間がかかったクエリ)
# Query 1: 4.93 QPS, 22.32x concurrency, ID 0xF27CEE401A7A6E75977FE1A782B008D1 at byte 21388583
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.46
# Time range: 2025-04-29T20:01:05 to 2025-04-29T20:01:51
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 55 227
# Exec time 47 1027s 3s 9s 5s 7s 1s 4s
# Lock time 3 438us 1us 4us 1us 2us 0 1us
# Rows sent 0 227 1 1 1 1 0 1
# Rows examine 43 12.32M 55.57k 55.57k 55.57k 55.57k 0 55.57k
# Query size 0 30.37k 137 137 137 137 0 137
# String:
# Databases db_stg (226/99%), db_prd (1/0%)
# Hosts [IP-MASKED] (115/50%), [IP-MASKED] (112/49%)
# Users [USER-MASKED]
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `db_stg` LIKE 'article'\G
# SHOW CREATE TABLE `db_stg`.`article`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT (COUNT(*)) AS `count` FROM article article
WHERE (status = 2 AND (now() BETWEEN published_at AND COALESCE(unpublished_at, now())))\G
クエリ #2 の詳細
# Query 2: 0.00 QPS, 0.02x concurrency, ID 0x252F1C654E3B43B4E6AA5BAAE7621FC4 at byte 21382760
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.20
# Time range: 2025-04-29T15:41:20 to 2025-04-29T20:01:51
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 17 72
# Exec time 13 292s 3s 7s 4s 6s 890ms 4s
# Lock time 1 165us 2us 4us 2us 2us 0 1us
# Rows sent 0 72 1 1 1 1 0 1
# Rows examine 13 3.91M 55.57k 55.57k 55.57k 54.03k 0 54.03k
# Query size 0 27.00k 370 440 383.97 420.77 18.26 363.48
# String:
# Databases db_prd (60/83%), db_stg (12/16%)
# Hosts [IP-MASKED] (30/41%), [IP-MASKED] (22/30%)... 1 more
# Users [USER-MASKED]
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS FROM `db_stg` LIKE 'article'\G
# SHOW CREATE TABLE `db_stg`.`article`\G
# SHOW TABLE STATUS FROM `db_stg` LIKE 'article_category'\G
# SHOW CREATE TABLE `db_stg`.`article_category`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT (COUNT(*)) AS `count` FROM article Article
WHERE ((Article.category_id in ([ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED])
OR Article.id in (
SELECT DISTINCT ArticleCategory.article_id AS `ArticleCategory__article_id`
FROM article_category ArticleCategory
WHERE ArticleCategory.category_id in ([ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED])
))
AND Article.status = 2
AND (now() BETWEEN Article.published_at AND COALESCE(Article.unpublished_at, now())))\G
クエリ #3 の詳細
# Query 3: 0.00 QPS, 0.00x concurrency, ID 0xCF1F9CF01C1DFFC9611C49D77BB5341B at byte 8538463
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.36
# Time range: 2025-04-27T21:00:16 to 2025-05-04T03:00:22
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 3 13
# Exec time 9 210s 12s 21s 16s 18s 2s 15s
# Lock time 24 3ms 2us 661us 233us 596us 286us 9us
# Rows sent 0 17.60k 1.35k 1.35k 1.35k 1.35k 0 1.35k
# Rows examine 1 499.02k 38.39k 38.39k 38.39k 36.57k 0 36.57k
# Query size 0 3.15k 248 248 248 248 0 248
# String:
# Databases db_stg
# Hosts [IP-MASKED]
# Users [USER-MASKED]
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS FROM `db_stg` LIKE 'article'\G
# SHOW CREATE TABLE `db_stg`.`article`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT DISTINCT Article.author_id AS `Article__author_id`
FROM article Article
WHERE (Article.status = 2
AND (now() BETWEEN Article.published_at AND COALESCE(Article.unpublished_at, now()))
AND category_id in ([ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED],[ID-MASKED]))\G
分析レポートの見方
pt-query-digestの出力は主に3つのセクションに分かれています：
-
全体サマリー: 全体のクエリ実行統計
- 総クエリ数、ユニーク数、QPS、実行時間など
-
プロファイル: クエリタイプごとの統計
- ランク付けされたクエリID
- 応答時間
- 呼び出し回数
- クエリの実際の内容
-
各クエリの詳細: 特定のクエリについての詳細情報
- 実行時間の分布
- ロック時間
- 送受信行数
- クエリの具体的な内容
🔍 結果の読み方のポイント
レポートの読み方で、特に重要なポイントがいくつかあるようです:
- Response time: クエリの応答時間の割合。これが大きいクエリが最適化の主な対象になります
- Calls: クエリの実行回数。頻繁に実行されるクエリは小さな最適化でも大きな効果があります
- R/Call: 1回の呼び出しあたりの応答時間。これが大きいクエリは特に注目すべきです
- Query: 実際のSQLクエリ。これを基に最適化方法を検討します
せっかくなのでCursor（Claude 3.7 Sonnet thinking）に分析結果を評価してもらいました
pt-query-digestのサマリーから以下のような問題点が見られます：
1. **全体的な統計:**
- 期間: 2025年4月27日〜5月4日
- 合計クエリ数: 407件（24種類のユニーククエリ）
- 非常に低いQPS（秒間クエリ数）
2. **実行時間の問題:**
- 総実行時間: 2146秒（約36分）
- 平均実行時間: 5秒（非常に遅い）
- 95パーセンタイル: 13秒（極端に遅いクエリが存在）
3. **トップクエリの問題:**
- 最も時間を消費しているクエリは `SELECT article` で全体の47.8%（1026秒）を占める
- 上位3クエリで全体の71.2%の時間を消費
- 特に `article` テーブルへのクエリが多く問題になっている
4. **データアクセスの問題:**
- 検査行数（Rows examine）が多い: 平均72k行、最大1.22M行
- 送信行数（Rows sent）との差が大きい: 検査行数の平均が72k行に対し送信は5.8k行
5. **主な問題クエリ:**
- `article`テーブルへの複数のSELECTクエリ
- `article_category`との結合クエリ
- `DELETE article_analytics`（129秒、6.0%）
- 複雑な`INSERT SELECT`クエリも遅延の原因
これらのクエリはインデックス最適化、クエリの書き直し、テーブル設計の見直しなどが必要です。
特に`article`テーブルに対するクエリの改善が最も効果的でしょう。
↓
第１位のクエリの改善方法を検討
提供されたクエリの詳細から、以下の問題点と改善策が考えられます：
## 問題点
1. **大量のデータスキャン**: 55,57k行を検査して単一のカウント値を返すだけ
2. **関数による非効率**: `now()`と`COALESCE()`の組み合わせがインデックス効率を下げている
3. **高頻度実行**: 4.93QPSで実行され、高い同時実行性（22.32x）
## 改善策
1. **インデックス最適化**:
CREATE INDEX idx_article_status_published_unpublished ON article(status, published_at, unpublished_at);
2. **クエリの書き換え**:
-- 現在の日時を変数に保存して一度だけ計算
SET @current_time = NOW();
SELECT COUNT(*) AS count FROM article
WHERE status = 2
AND published_at <= @current_time
AND (unpublished_at IS NULL OR unpublished_at >= @current_time);
3. **マテリアライズドビューの検討**:
公開中の記事数のような頻繁に必要とされる情報は、マテリアライズドビューやキャッシュテーブルを作成して定期的に更新する
4. **パーティショニング**:
`status`や`published_at`でテーブルをパーティショニングし、スキャン範囲を減らす
5. **アプリケーション側のキャッシュ**:
この集計情報をアプリケーションレベルでキャッシュし、頻繁なDBアクセスを回避
特に`status = 2`と日付範囲を組み合わせた複合インデックスが最も効果的でしょう。`COALESCE`関数の使用がインデックスの効率を下げているため、クエリ書き換えも重要です。
↓
うん。いい感じですね。これだけでも、改善できそうな気がしますし、やる気も出そうです。
🎯 まとめ
自分でもちょっと回りくどいことをしているなーと思う部分はありつつ、
正直、弊社内ではここまでの方法すらきちんと確立してきておらず、
もう本当に生のスロークエリを目視したりしているだけだったりするので
少なくともそこからは一歩二歩進めたかな、と思っています。
余談：pt-query-digestを含む「Perconaツールキット」について
わたくし知らなかったので、Claudeに聞いてみました。
Perconaツールキットには、pt-query-digestの他にも多くの便利なデータベース管理・分析ツールが
含まれています。最新情報を確認しましょう。
Perconaツールキットには、pt-query-digestの他にも多数のデータベース管理・分析ツールが含まれています。
Percona Toolkitは、MySQLやMongoDB、システムタスクを実行するための
高度なコマンドラインツールのコレクションで、手動で実行するには難しすぎる作業を効率化するために
開発されています。
主なツールには以下のようなものがあります：
1. **データベース構造・設定関連**
- pt-config-diff: データベース設定の差分を比較
- pt-duplicate-key-checker: 重複したインデックスをチェック
- pt-index-usage: インデックスの使用状況を分析
- pt-online-schema-change: オンライン状態でテーブル構造変更
2. **パフォーマンス分析**
- pt-query-digest: クエリのパフォーマンス分析（今回使用したツール）
- pt-visual-explain: クエリ実行計画の視覚化
- pt-index-usage: インデックス使用状況の分析
3. **レプリケーション関連**
- pt-table-checksum: レプリカサーバーのデータチェックサム作成
- pt-table-sync: テーブルの同期
- pt-heartbeat: レプリケーションの遅延監視
- pt-replica-find: レプリカサーバーの検出
4. **システム状態確認**
- pt-mysql-summary: MySQLサーバーの概要情報を表示
- pt-mongodb-summary: MongoDBサーバーの概要情報を表示
- pt-pg-summary: PostgreSQLサーバーの概要情報を表示
- pt-stalk: 問題発生時に診断情報を収集
5. **メンテナンス**
- pt-archiver: テーブルデータのアーカイブ
- pt-kill: 問題のあるクエリを特定して停止
その他にも多くのツールがあり、現在はMySQL、MariaDB、MongoDB、PostgreSQLをサポートし、AWSやGoogleクラウド、Microsoft Azureなどの主要クラウドプロバイダーとも完全に互換性があります。
最新版はPercona Toolkit 3.7.0（2024年12月リリース）で、MySQL 8.4のサポートが追加されています。詳しい説明や各ツールの使い方は[Percona Toolkitの公式ドキュメント](https://docs.percona.com/percona-toolkit/)を参照すると良いでしょう。
インデックスの使用状況を分析、とか個人的に気になりました。
とりあえず知れてよかったです。