RDS / Aurora のパフォーマンスインサイト API を使って S3 に SQL トップ 10 とその待機イベント内訳を転記する

こちらは[この記事](https://qiita.com/hmatsu47/items/b689db489e75836b0d7d)の続きです。

 - **[RDS / Aurora のパフォーマンスインサイト API を使って S3 に分単位の SQL トップ 10 を転記する](https://qiita.com/hmatsu47/items/b689db489e75836b0d7d)**

今回は、SQL トップ 10 に加えて、**SQL トップ 10 の待機イベント内訳**も（同じ S3 バケットに別のプレフィックスを付けて）転記します。

# 待機イベント内訳が必要になるケース

処理時間の長い SQL（文）のチューニングを行う場合、基本的には`EXPLAIN`などを使うことで原因調査が可能です。
ただ、

 - 単純な`INSERT`文や主キーで一意に絞り込んだ`UPDATE`文が遅い
 - ほかに処理時間が長い更新・削除や DDL が並行して実行された形跡がなく、ロック待ちで遅くなったとは考えづらい
 - 特に CPU 使用率や I/O 負荷の上昇なども見られない

など、原因がはっきりしないケースもまれに発生します。

このような場合には、対象の SQL（文）についての待機イベント内訳があると調査しやすくなります。

# コードの変更

[GitHub](https://github.com/hmatsu47/performance_insights_to_s3) には`lambda_function_events.py`というファイル名で置いてありますが、[前回](https://qiita.com/hmatsu47/items/b689db489e75836b0d7d#s3-%E8%BB%A2%E8%A8%98%E7%94%A8-lambda-%E9%96%A2%E6%95%B0%E3%81%AE%E5%86%85%E5%AE%B9)と同じファイル名`lambda_function.py`の内容を置き換えて登録します（または、Lambda の Handler で呼び出すファイル名を変更します）。

```python:lambda_function.py
import boto3
from datetime import date, datetime, timedelta
import os
import time

db_id     = os.environ["DB_ID"]
s3_bucket = os.environ["S3_BUCKET"]

def lambda_handler(event, context):
    # 1時間前の時刻を取得（UTC）→対象時間のPerformance InsightsからS3へ
    lasthour = (datetime.today() + timedelta(hours = -1)).replace(minute=0, second=0, microsecond=0)

    print("Export: " + (lasthour + timedelta(hours = 9)).strftime('%Y/%m/%d %H:00-%H:59'))
    # 1分ごとに上位最大10件の正規化SQLを取得してS3へ転記
    for minute in range(60):
        # Performance Insightsからデータを取得
        starttime = lasthour + timedelta(minutes = minute)
        metric    = "db.load.avg"
        periods   = 60
        groupby   = {
                    "Group": "db.sql_tokenized",
                    "Dimensions": [
                        "db.sql_tokenized.statement",
                        "db.sql_tokenized.id"
                    ],
                    "Limit": 10
                    }
        filter    = {}
        response = pi_fetch(db_id, starttime, metric, periods, groupby, filter)
        if len(response["Keys"]):
            # 対象となる時刻（分単位）のデータがあればS3へ転記（プレフィクスの時刻はJST）
            s3_prefix  = db_id + "/" + (starttime + timedelta(hours = 9)).strftime('%Y/%m/%d/%Y%m%d%H%M') + "_" + db_id + ".tsv"
            exporttime = starttime.strftime('%Y-%m-%dT%H:%M:%SZ')
            body_data  = "start_time\tsql_tokenized\ttotal\n"
            event_s3_prefix = db_id + "_wait_events/" + (starttime + timedelta(hours = 9)).strftime('%Y/%m/%d/%Y%m%d%H%M') + "_" + db_id + "_wait_events.tsv"
            event_body_data = "start_time\tsql_tokenized\tevent_type\tevent_name\ttotal\n"
            # すべてのKeysから正規化SQLと合計値を抽出
            for item in response["Keys"]:
                sqltk = item["Dimensions"]["db.sql_tokenized.statement"]
                sqlid = item["Dimensions"]["db.sql_tokenized.id"]
                total = item["Total"]
                body_data += exporttime + "\t" + sqltk + "\t" + str(total) + "\n"
                # 正規化SQL別の待機イベントを取得してS3へ転記
                event_groupby  = {
                                "Group": "db.wait_event",
                                "Dimensions": [
                                "db.wait_event.type",
                                "db.wait_event.name"
                                ],
                                "Limit": 10
                                }
                event_filter   = {
                                "db.sql_tokenized.id": sqlid
                                } 
                event_response = pi_fetch(db_id, starttime, metric, periods, event_groupby, event_filter)
                if len(event_response["Keys"]):
                    # 対象となる時刻（分単位）の待機イベントがあればS3へ転記
                    for event_item in event_response["Keys"]:
                        event_type       = event_item["Dimensions"]["db.wait_event.type"]
                        event_name       = event_item["Dimensions"]["db.wait_event.name"]
                        event_total      = event_item["Total"]
                        event_body_data += exporttime + "\t" + sqltk + "\t" + event_type + "\t" + event_name + "\t" + str(event_total) + "\n"
            # S3へ
            s3_put(s3_bucket, s3_prefix, body_data)
            s3_put(s3_bucket, event_s3_prefix, event_body_data)
    return "Completed."

def pi_fetch(db_id, starttime, metric, periods, groupby, filter):
    pi_client = boto3.client("pi")
    response = pi_client.describe_dimension_keys(
            ServiceType="RDS",
            Identifier=db_id,
            StartTime=starttime,
            EndTime=starttime + timedelta(minutes = 1),
            Metric=metric,
            PeriodInSeconds=periods,
            GroupBy=groupby,
            Filter=filter
            )
    time.sleep(0.1)
    return response

def s3_put(bucket, key, body):
    s3_client = boto3.client("s3")
    s3_client.put_object(
            Bucket=bucket,
            Key=key,
            Body=body
            )
```

---

**2021/05/31 追記：**
対象インスタンスによっては API のレートリミットに引っかかることがわかりましたので、API 呼び出しごとに`time.sleep(0.1)`を入れるようにしました。必要に応じて調整してください。

※複数同時並行で実行すると、高確率で API のレートリミットに引っかかります。ご注意ください。

---

コード以外の設定は基本的に[前回](https://qiita.com/hmatsu47/items/b689db489e75836b0d7d#%E8%A8%AD%E5%AE%9A%E3%81%AA%E3%81%A9)と同じですが、**タイムアウト時間のみ 10 ～ 15 分程度に延長**します。

# 実際に使い物になるのか？

…と、ここまで進めておいていまさら感のある話になってしまいますが、**分単位の集計情報で実際に使い物になるのか？と言われると正直微妙**です。

というのも、

 - 原因調査が必要なケースは大体個々の SQL（文）を特定して待機イベントの内訳を把握する必要がある一方、正規化・トークン化した集計を見ても個々の状況は把握しづらい

のと、

 - 分単位では多くのケースで粒度が粗すぎて対象の SQL（文）を捕捉できない可能性があり、かといって秒単位では転記に時間が掛かりすぎて実用的ではない

のが主な理由です。

というわけで、**使えそうなシチュエーションなら試してみてもいいかも**ぐらいのスタンスで受け取ってください。