AWS CloudWatchのログをPythonで整形→pt-query-digestツールでMySQLスロークエリを分析してみた


## 📝 はじめに

自社で月間PV数1500～2000万以上のメディアサイトを運営しており、
私はそのメインエンジニアを担当させてもらっています。
日々、保守運用から新規開発のリードまでいろいろとやっていますが、なにをするにも可用性。パフォーマンス。
その対策のためにも、スロークエリ調査自体の効率化、最適化も大事だよなーーと思いつつ、自分なりにこれもまあアリかも、という方法を策定？したので、残しておきたいと思います。
ざっくりいうと、AWS CloudWatchからCSVデータをダウンロードし、Google ColabにてPythonで整形して、pt-query-digestツールで解析するまでの一連の流れですね。
そうすると、なにがオイシイのか。

```mermaid
graph LR
    A[AWS CloudWatch] --> B[CSVダウンロード]
    B --> C[Pythonで整形]
    C --> D[formatted_slowquery.log作成]
    D --> E[pt-query-digestで分析]
    E --> F[分析結果の確認]
    
    style A fill:#f9d5e5,stroke:#333
    style B fill:#eeeeee,stroke:#333
    style C fill:#d3f0ee,stroke:#333
    style D fill:#eeeeee,stroke:#333
    style E fill:#d3f0ee,stroke:#333
    style F fill:#f9d5e5,stroke:#333
```

### Thanks for the reference! 👏

pt-query-digestとは？
pt-query-digestと出合わせてくれた下記記事で知ることができます。

https://zenn.dev/levtech/articles/6607ee10b57656

## 🌟 必要なもの・想定環境

- Mac（Brewコマンドがインストールされている前提）
- AWSアカウント、およびCloudWatch権限
- Google Colab（Python実行できればなんでもOK）

## 📊 AWS CloudWatchからCSVダウンロード

CloudWatchのログのインサイトからCSVデータをエクスポートします。

※
CloudWatchのログのインサイトは、それ自体でも高度な分析機能を提供していますが、
特定の形式（pt-query-digest用）に変換するためには追加の処理が必要です。
そのためにダウンロードします。

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/591019/44473773-1c6a-42ef-bdcb-37e99e8423af.png)

1. CloudWatchのログのインサイトに移動
2. 分析したいロググループを選択
3. 必要なフィルタ条件を設定（例：`fields @timestamp, @message, @log`、あと期間指定も）
4. クエリを実行後、「CSVとしてダウンロード」を選択

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/591019/03137f92-bcd6-48b8-b9b7-6f7a554fcd06.png)

:::note warn
awsコマンドでも直接、分析可能な形式でダウンロードすることもできますが、期間指定や件数がうまくいっていないため、一旦断念しています。
期間や件数、各クエリの内容を一旦確認してからダウンロードできるという点ではGUIのほうが良いという実感もありました。
:::

## 💻 Pythonで整形する

最初はダウンロードしたCSVをそのままpt-query-digestに投げて分析できるか？とやってみたのですが
形式がマッチしていないようでエラーに。
今回はPythonで整形する方法を採用しました。
CSVはかなり大容量になるので、ちょこちょこ手で直すわけにもいかず
Google Colabを使って、CSVデータをpt-query-digestで解析可能な形式に変換します。
（まあ、やっていることとしては、pt-query-digest向けにダブルクォーテーションを消すくらいなんですけれど。。）

![スクリーンショット 2025-05-04 15.56.57.jpg](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/591019/73e8386c-3469-4022-b1cc-96de13810e91.jpeg)

<details>
<summary>Pythonコード全文</summary>

```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')
```

</details>

### 🔑 コードのポイント:

1. CSVファイルを読み込み、構造を確認
2. `message`カラムからダブルクォートを削除
3. 整形したデータを`formatted_slowquery.log`として保存
4. 簡単な統計分析も実施（クエリ時間の平均・中央値・最大値など）

:::note alert
以前の処理結果が残っている場合、以前のキャッシュが何らかの影響で古い情報が処理されるケースがあるかもしれません。そのため一度Colabをリロードし、古いlogs-insights-results.csvが存在する場合は事前に削除してから作業してください。
:::

## 🛠 pt-query-digestでの分析実行

ローカルに`formatted_slowquery.log`がDLされているはずなので
それを使ってpt-query-digestツールで詳細な分析を行います。

### ツール分析実行

事前にツールのインストールが必要。brewでの記載。

```bash
brew install percona-toolkit
```

そして分析を実行:

```bash
pt-query-digest formatted_slowquery.log > query_analysis_report.txt
```

## 📈 分析結果の確認

query_analysis_report.txtとして生成された実行結果のレポートを確認できます。

<details><summary>実際の分析結果の一部</summary>

# pt-query-digestの分析結果例

※以下の情報をマスキングしています：

1. データベース名：実際のデータベース名を一般的な名前（db_stg, db_prd）に置き換えました
1. IPアドレス：すべてのIPアドレスを[IP-MASKED]に置き換えました
1. ユーザー名：管理者アカウント名を[USER-MASKED]に置き換えました
1. カテゴリ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
```

</details>


<details>
<summary>分析レポートの見方</summary>

pt-query-digestの出力は主に3つのセクションに分かれています：

1. **全体サマリー**: 全体のクエリ実行統計
   - 総クエリ数、ユニーク数、QPS、実行時間など

2. **プロファイル**: クエリタイプごとの統計
   - ランク付けされたクエリID
   - 応答時間
   - 呼び出し回数
   - クエリの実際の内容

3. **各クエリの詳細**: 特定のクエリについての詳細情報
   - 実行時間の分布
   - ロック時間
   - 送受信行数
   - クエリの具体的な内容
</details>

### 🔍 結果の読み方のポイント

レポートの読み方で、特に重要なポイントがいくつかあるようです:

1. **Response time**: クエリの応答時間の割合。これが大きいクエリが最適化の主な対象になります
2. **Calls**: クエリの実行回数。頻繁に実行されるクエリは小さな最適化でも大きな効果があります
3. **R/Call**: 1回の呼び出しあたりの応答時間。これが大きいクエリは特に注目すべきです
4. **Query**: 実際のSQLクエリ。これを基に最適化方法を検討します

### :robot: せっかくなので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/)を参照すると良いでしょう。
```

インデックスの使用状況を分析、とか個人的に気になりました。
とりあえず知れてよかったです。

---

## 参考文献

- [Percona Toolkit Documentation](https://www.percona.com/doc/percona-toolkit/LATEST/index.html)
- [AWS CloudWatch Logs Insights ユーザーガイド](https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/AnalyzingLogData.html)