ISUCON過去問のボトルネックをNew Relic APMで確認する

記事タイトルとURLをコピーする

こんにちはマネージドサービス部 大城です。

前回のブログ の続きを書きます。今回は Python で試してみます。

New Relic APM をインストールした後、ボトルネックがどこにあるのか確認して、少しだけチューニングします。

前準備

前回のブログ を参考に Python にNew Relic APMを入れます。

t3 などのバースト型のインスタンスを使うとスコアが安定しなかったので、今回は c6a.xlarge で進めました。

やってみた

チューニングなしの状態

環境ができたらチューニングなしで一度ベンチマークを走らせてみます。

ベンチマーク1回目

チューニングなし状態のスコアは 2986 でした。

ベンチマーク1回目 スコア: 2986

sudo su - isucon
./bench run --enable-ssl
・
・
2024-04-20T00:59:44.012Z    info    staff-logger    bench/bench.go:260  ベンチマーク走行時間: 1m0.10471086s
2024-04-20T00:59:44.013Z    info    isupipe-benchmarker ベンチマーク走行終了
2024-04-20T00:59:44.013Z    info    isupipe-benchmarker 最終チェックを実施します
2024-04-20T00:59:44.014Z    info    isupipe-benchmarker 最終チェックが成功しました
2024-04-20T00:59:44.014Z    info    isupipe-benchmarker 重複排除したログを以下に出力します
2024-04-20T00:59:44.015Z    info    staff-logger    bench/bench.go:277  ベンチエラーを収集します
2024-04-20T00:59:44.015Z    info    staff-logger    bench/bench.go:285  内部エラーを収集します
2024-04-20T00:59:44.015Z    info    staff-logger    bench/bench.go:301  シナリオカウンタを出力します
2024-04-20T00:59:44.016Z    info    isupipe-benchmarker 配信を最後まで視聴できた視聴者数    {"viewers": 10}
2024-04-20T00:59:44.016Z    info    staff-logger    bench/bench.go:323  [シナリオ aggressive-streamer-moderate] 30 回成功
2024-04-20T00:59:44.017Z    info    staff-logger    bench/bench.go:323  [シナリオ dns-watertorture-attack] 91 回成功
2024-04-20T00:59:44.017Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-cold-reserve] 92 回成功
2024-04-20T00:59:44.018Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-moderate] 17 回成功
2024-04-20T00:59:44.018Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-report] 38 回成功, 4 回失敗
2024-04-20T00:59:44.019Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-spam] 32 回成功
2024-04-20T00:59:44.022Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer] 10 回成功
2024-04-20T00:59:44.022Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ viewer-report-fail] 4 回失敗
2024-04-20T00:59:44.023Z    info    staff-logger    bench/bench.go:329  DNSAttacker並列数: 6
2024-04-20T00:59:44.023Z    info    staff-logger    bench/bench.go:330  名前解決成功数: 9666
2024-04-20T00:59:44.024Z    info    staff-logger    bench/bench.go:331  名前解決失敗数: 3
2024-04-20T00:59:44.024Z    info    staff-logger    bench/bench.go:335  スコア: 2986

New Relic画面確認(チューニングなしの状態)

APMのSummary画面を見てみます。Web transactions time でMySQLの処理時間が多いことが確認できます。最初にMySQLのDDLを確認してindex作成したほうが良さそうです。

チューニングなし

公式ブログ ISUCON13 問題の解説と講評 でもindexに関する記載がありました。

インデックスの作成

参照実装の初期状態では、データベース上のインデックスがこれでもかっ!というほど存在しておりません。

indexを作成する

公式ブログ ISUCON13 問題の解説と講評 に書かれているindexをとりあえず作成してみました。

index作成

sudo mysql isupipe
alter table livestream_tags add index idx_livestream_id (livestream_id);
alter table livestream_tags add index idx_tag_id_livestream_id (tag_id, livestream_id);
alter table livestreams add index idx_user_id (user_id);
alter table icons add index idx_user_id (user_id);
alter table livecomments add index idx_livestream_id (livestream_id);
alter table themes add index idx_user_id (user_id);
alter table reactions add index idx_livestream_id(livestream_id,created_at);
alter table livestream_viewers_history add index idx_user_id_livestream_id  (user_id, livestream_id);
alter table ng_words add index idx_livestream_id_user_id (livestream_id,user_id);
alter table reservation_slots add index idx_end_at (end_at);
alter table livecomment_reports add index idx_livestream_id(livestream_id);
exit

ベンチマーク2回目

index作成後の スコアは 3268 でした。少し上がりました。

ベンチマーク2回目 スコア: 3268

sudo su - isucon
./bench run --enable-ssl
・
・
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:260  ベンチマーク走行時間: 1m0.077491739s
2024-04-20T01:05:48.446Z    info    isupipe-benchmarker ベンチマーク走行終了
2024-04-20T01:05:48.446Z    info    isupipe-benchmarker 最終チェックを実施します
2024-04-20T01:05:48.446Z    info    isupipe-benchmarker 最終チェックが成功しました
2024-04-20T01:05:48.446Z    info    isupipe-benchmarker 重複排除したログを以下に出力します
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:277  ベンチエラーを収集します
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:285  内部エラーを収集します
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:301  シナリオカウンタを出力します
2024-04-20T01:05:48.446Z    info    isupipe-benchmarker 配信を最後まで視聴できた視聴者数    {"viewers": 12}
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:323  [シナリオ aggressive-streamer-moderate] 21 回成功, 28 回失敗
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:323  [シナリオ dns-watertorture-attack] 152 回成功
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-cold-reserve] 116 回成功, 30 回失敗
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-moderate] 10 回成功
2024-04-20T01:05:48.446Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-report] 37 回成功, 5 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-spam] 22 回成功, 28 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer] 12 回成功
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ aggressive-streamer-moderate-fail] 28 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ streamer-cold-reserve-fail] 30 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ viewer-report-fail] 5 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ viewer-spam-fail] 28 回失敗
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:329  DNSAttacker並列数: 6
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:330  名前解決成功数: 13868
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:331  名前解決失敗数: 86
2024-04-20T01:05:48.447Z    info    staff-logger    bench/bench.go:335  スコア: 3268

New Relic画面確認(index作成後)

再度、APMのSummary画面を見てみます。Web transactions time でMySQLの処理時間が少し減ったことが確認できます。

index作成後

もう少し精査してindexを作成するとスコアが良くなりそうですが、次のチューニングを試してみます。

N+1(エヌプラスワン)問題の解消

N+1問題とは、1つの親オブジェクトに対して、子オブジェクトの数だけ別々のクエリを発行してしまう問題のことです。

参考記事

N+1問題がなんもわからんというだけの記事

[解説] SQLクエリのN+1問題 #Go - Qiita

New Relicのトレース画面を見ていると明らかにN+1の動きをしているトランザクションがあったので確認してみます

moderate_handler 関数のトレース画面で delete が1991回実行されていることがわかります。これはワンクリックでdelete が1991回実行されていることを表しています。

delete 1991回

また画面下の Transaction trace でも delete が大量にあることがわかります。delete処理がチリツモになって処理時間が延びています。

Transaction trace

ソースコードを普段書かない私が直すと日が暮れそうなので Amazon Bedrock(Claude 3 Opusモデル)に修正してもらいましたw

Amazon Bedrock 入力プロンプト

このpythonのコードはSQLを多く実行する N+1 の問題があります。修正版を作ってください。

def moderate_handler(livestream_id: int) -> tuple[dict[str, Any], int]:
    verify_user_session()

    user_id = session.get(Settings.DEFAULT_USER_ID_KEY)
    if not user_id:
        raise HttpException("failed to find user-id from session", UNAUTHORIZED)

    req = get_request_json()
    if not req or "ng_word" not in req:
        raise HttpException(
            "failed to decode the request body as json",
            BAD_REQUEST,
        )

    conn = engine.raw_connection()

    try:
        conn.start_transaction()
        c = conn.cursor(dictionary=True)

        # 配信者自身の配信に対するmoderateなのかを検証
        sql = "SELECT * FROM livestreams WHERE id = %s AND user_id = %s"
        c.execute(sql, [livestream_id, user_id])
        owned_livestreams = c.fetchall()
        if owned_livestreams is None or len(owned_livestreams) == 0:
            raise HttpException(
                "A streamer can't moderate livestreams that other streamers own",
                BAD_REQUEST,
            )

        sql = "INSERT INTO ng_words(user_id, livestream_id, word, created_at) VALUES (%s, %s, %s, %s)"
        c.execute(
            sql,
            [
                user_id,
                livestream_id,
                req["ng_word"],
                datetime.now().timestamp(),
            ],
        )

        word_id = c.lastrowid
        # app.logger.info(f"word_id: {word_id}, word: {req['ng_word']}")

        sql = "SELECT * FROM ng_words WHERE livestream_id = %s"
        c.execute(sql, [livestream_id])
        rows = c.fetchall()
        if rows is None:
            raise HttpException("failed to get NG words", INTERNAL_SERVER_ERROR)
        ngwords = [models.NGWord(**row) for row in rows]

        # NGワードにヒットする過去の投稿も全削除する
        for ngword in ngwords:
            sql = "SELECT * FROM livecomments"
            c.execute(sql)
            rows = c.fetchall()
            if rows is None:
                app.logger.warn("failed to get livecomments")
                raise HttpException(
                    "failed to get livecomments",
                    INTERNAL_SERVER_ERROR,
                )
            livecomments = [models.LiveCommentModel(**row) for row in rows]

            for livecomment in livecomments:
                # app.logger.info(f"delete: {livecomment}")
                sql = """
                    DELETE FROM livecomments
                    WHERE
                    id = %s AND
                    (SELECT COUNT(*)
                    FROM
                    (SELECT %s AS text) AS texts
                    INNER JOIN
                    (SELECT CONCAT('%%', %s, '%%')    AS pattern) AS patterns
                    ON texts.text LIKE patterns.pattern) >= 1;
                """
                c.execute(sql, [livecomment.id, livecomment.comment, ngword.word])
        return asdict(models.ModerateResponse(word_id=word_id)), CREATED
    except DatabaseError as err:
        conn.rollback()
        raise err
    finally:
        conn.commit()
        conn.close()

Amazon Bedrock 回答

修正版のコードは以下のようになります。N+1問題を解決するために、SQLクエリを最適化し、必要なデータをまとめて取得するようにしています。

def moderate_handler(livestream_id: int) -> tuple[dict[str, Any], int]:
    verify_user_session()
    user_id = session.get(Settings.DEFAULT_USER_ID_KEY)
    if not user_id:
        raise HttpException("failed to find user-id from session", UNAUTHORIZED)

    req = get_request_json()
    if not req or "ng_word" not in req:
        raise HttpException(
            "failed to decode the request body as json", BAD_REQUEST,
        )

    conn = engine.raw_connection()
    try:
        conn.start_transaction()
        c = conn.cursor(dictionary=True)
        
        # 配信者自身の配信に対するmoderateなのかを検証
        sql = "SELECT * FROM livestreams WHERE id = %s AND user_id = %s"
        c.execute(sql, [livestream_id, user_id])
        owned_livestreams = c.fetchall()
        if owned_livestreams is None or len(owned_livestreams) == 0:
            raise HttpException(
                "A streamer can't moderate livestreams that other streamers own", BAD_REQUEST,
            )

        # 新しいNG wordを追加
        sql = "INSERT INTO ng_words(user_id, livestream_id, word, created_at) VALUES (%s, %s, %s, %s)"
        c.execute(
            sql,
            [
                user_id,
                livestream_id,
                req["ng_word"],
                datetime.now().timestamp(),
            ],
        )
        word_id = c.lastrowid

        # NG wordを取得
        sql = "SELECT * FROM ng_words WHERE livestream_id = %s"
        c.execute(sql, [livestream_id])
        rows = c.fetchall()
        if rows is None:
            raise HttpException("failed to get NG words", INTERNAL_SERVER_ERROR)
        ngwords = [models.NGWord(**row) for row in rows]

        # NG wordにヒットするlivecommentsを取得
        ng_patterns = [f"%{ngword.word}%" for ngword in ngwords]
        sql = """
            SELECT lc.*
            FROM livecomments lc
            WHERE lc.livestream_id = %s
              AND EXISTS (
                SELECT 1
                FROM ng_words nw
                WHERE nw.livestream_id = %s
                  AND lc.comment LIKE CONCAT('%%', nw.word, '%%')
              )
        """
        c.execute(sql, [livestream_id, livestream_id])
        rows = c.fetchall()
        if rows is None:
            app.logger.warn("failed to get livecomments")
            raise HttpException(
                "failed to get livecomments", INTERNAL_SERVER_ERROR,
            )
        livecomments = [models.LiveCommentModel(**row) for row in rows]

        # NG wordにヒットするlivecommentsを削除
        livecomment_ids = [livecomment.id for livecomment in livecomments]
        if livecomment_ids:
            sql = "DELETE FROM livecomments WHERE id IN (%s)"
            c.execute(sql, [",".join(map(str, livecomment_ids))])

        return asdict(models.ModerateResponse(word_id=word_id)), CREATED

    except DatabaseError as err:
        conn.rollback()
        raise err
    finally:
        conn.commit()
        conn.close()
主な変更点は以下のとおりです。 1. NG wordsを取得するSQLクエリを1回のみ実行するように変更しました。 2. NG wordにヒットするlivecommentsを取得するSQLクエリを最適化し、EXISTS句を使用して効率的に取得するようにしました。 3. NG wordにヒットするlivecommentsを削除する際に、個別のDELETE文を実行するのではなく、IN句を使用して一括で削除するようにしました。 これらの変更により、SQLクエリの実行回数を減らし、パフォーマンスを改善することができます。

(すげー、修正されていそう)

Amazon Bedrock が修正したソースコードを /home/isucon/webapp/python/app.py にデプロイしアプリを再起動します

sudo systemctl restart isupipe-python.service
ベンチマーク3回目

少しだけ良くなりましたが、あまりスコアは変わらず 3277 でした。

ベンチマーク3回目 スコア: 3277

sudo su - isucon
./bench run --enable-ssl
・
・
2024-04-20T02:23:18.493Z    info    staff-logger    bench/bench.go:260  ベンチマーク走行時間: 1m0.754929086s
2024-04-20T02:23:18.493Z    info    isupipe-benchmarker ベンチマーク走行終了
2024-04-20T02:23:18.493Z    info    isupipe-benchmarker 最終チェックを実施します
2024-04-20T02:23:18.494Z    info    isupipe-benchmarker 最終チェックが成功しました
2024-04-20T02:23:18.494Z    info    isupipe-benchmarker 重複排除したログを以下に出力します
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:277  ベンチエラーを収集します
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:285  内部エラーを収集します
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:301  シナリオカウンタを出力します
2024-04-20T02:23:18.494Z    info    isupipe-benchmarker 配信を最後まで視聴できた視聴者数    {"viewers": 11}
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ aggressive-streamer-moderate] 35 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ dns-watertorture-attack] 138 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-cold-reserve] 117 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ streamer-moderate] 27 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-report] 43 回成功, 1 回失敗
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer-spam] 37 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [シナリオ viewer] 11 回成功
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:323  [失敗シナリオ viewer-report-fail] 1 回失敗
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:329  DNSAttacker並列数: 6
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:330  名前解決成功数: 14449
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:331  名前解決失敗数: 0
2024-04-20T02:23:18.494Z    info    staff-logger    bench/bench.go:335  スコア: 3277

New Relic画面確認(N+1問題解消後)

moderate_handler の処理時間が減り、スループットが上がったことがわかります。 支配的だった delete (緑部分)が大幅に減ったことがわかります。

N+1解消後

このあたりで今回は切り上げます。いろいろやっていると楽しいので、無限に時間が溶けてしまいます。

参考

ボトルネックはどこから手を付ければよいか

ケースによるので、明確な答えはないのですが参考として書きます。ボトルネックは大きいもの(支配的なもの)から対応したほうが解消が早いです。

支配的なリクエストを切り分ける際の参考として New Relic APM -> Transactions -> Most time consuming の画面が役立つので紹介します。

この画面はデフォルトだと 処理時間 x リクエスト数 の多い順に集計されています。言い換えると支配的なリクエスト順に並んでいることになります。

これを上から順に 計測 -> 修正対応 を続けていくと、ボトルネックが移動していきます。

ボトルネック

参考記事 New Relic APMのMost time consumingを特定のUser Agentでフィルタして分析する #NewRelic - Qiita

生成AIでソースコードを直して良いのか

ISUCON13 問題の解説と講評 にAIを利用しても構わないと記載があります。そのため利用すること自体は問題ないようです。

また、ChatGPTが登場して以降初めてのISUCONであることも今回の大きな特徴の一つです。AIの利用はソフトウェア開発においてすでに切り離せないものとなっており、ISUCONにおいても当たり前に使用できたほうがいいと考えました。そこで明確にレギュレーションに「開発において、AIを活用したコードの分析、生成等を利用しても構わない。」と記しています。

今回たまたま生成AIが修正した moderate_handler 関数をデプロイしてうまく動きましたが、他の関数で試したところ、エラーになることが多々ありました。

プロンプトをもう少し工夫すると精度が上がると考えられますが、参考にする程度に留めておいたほうが良いと思います。

最後に

もう少しスコアを延ばしたかったのですが難しいですね。勉強不足です。

この記事を書くために、いろんな方のブログを参考にさせていただきました。ありがとうございました。

(検証が終わったら速やかにインスタンスを削除しましょう。消し忘れに注意ください)

大城 慶明 (記事一覧)

マネージドサービス部

2022年10月サーバーワークスに入社、沖縄からリモート勤務。AWSを勉強中。沖縄では大城が多いので「よっさん」と呼ばれています。AWS13冠。NRUG沖縄支部運営。X @yo_ohshiro