【ISUCONで始める】New Relicによるパフォーマンスチューニングを体験してみよう！

はじめに

この記事では、ISUCON¹の過去問（ISUCON13）を題材に、New Relic を活用したパフォーマンスチューニングを実践してみます。

主な想定読者は New Relic をまだ触ったことがない方で、この記事をきっかけに

• 「New Relic 触ってみたい！」
• 「New Relic を引っさげてISUCONに参加してみたい！」

と思っていただければ嬉しいです！

記事の前半では環境構築の流れを一通りご説明し、後半では実際にチューニングを行います。

New Relic はフリープランを利用します。
フリープランの概要については「New Relic フリープランで始めるオブザーバビリティ！ #初心者 - Qiita」をご参照ください。簡単にまとめると以下のような太っ腹仕様になっています。

• 全機能を利用可能なFull platform userを1名分使える
• 100GB/月までデータ転送が可能
• クレジットカードの登録不要

注意事項

• ISUCONの過去問環境を構築するにあたりAWSを利用しますが、利用料金が発生する可能性があることにご留意ください。
• ISUCONの言語にはPythonを使用します。
• 本記事で使用しているローカルPCのOSはmacOS Sequoiaです。

環境構築

それでは早速、環境構築から始めましょう

ISUCON過去問環境の構築

公式で紹介されている環境構築方法のうち、今回はAWSを使って環境を構築します。

まず、「matsuu/aws-isucon: ISUCON過去問をAWS環境で構築するための一式」からami-006d211cb716fe8a0を選択、「AMIからインスタンスを起動」をクリックし EC2インスタンスを起動します。

参考までに、筆者は以下の設定でインスタンスを作成しました。

• インスタンスタイプはc5.largeを選択
• 「自分のIP」からの SSH トラフィックを許可
• インターネットからの HTTPS トラフィックを許可

（また、インスタンス作成後にEIPを関連付けることで、インスタンスを停止してもIPアドレスが変わらないようにしました。）

インスタンスの作成が完了したら、ローカルPCのhostsファイルに以下を追記しておきます。

<YOUR_EC2_IP> https://pipe.u.isucon.local/

(例) 192.0.2.1 https://pipe.u.isucon.local/

続いて、 「ISUCON13 当日マニュアル」を参考にしながら初期設定を行います。

1. SSHでEC2にログインします。

   ssh -i <PATH_TO_YOUR_PRIVATE_KEY> ubuntu@<YOUR_EC2_IP>
   
   (例) ssh -i ~/.ssh/my-key.pem ubuntu@192.0.2.1
   

2. isuconユーザーに切り替えます。

   sudo -i -u isucon
   

3. DBに初期データを投入します。

   ~/webapp/sql/init.sh
   

4. 初期状態ではGoによる実装が起動しているため、Pythonに切り替えます。

   sudo systemctl disable --now isupipe-go.service
   sudo systemctl enable --now isupipe-python.service
   

アプリケーションにAPMを入れる

APM（Application Performance Monitoring）とは、アプリケーションの動作状況をリアルタイムで監視・分析し、パフォーマンスの問題を特定して改善するためのツールです。
ISUCONにおける活用方法としては、アプリケーションの各部分（データベースクエリ、外部API呼び出し、特定の処理など）の実行時間を把握し、パフォーマンスのボトルネック特定に役立てることができます。

公式ドキュメントの「Install the Python agent」を参考に進めます。

1. newrelicパッケージをインストールします。ISUCON13のPython環境ではpipenvが使われているようなので、pipenvを使ってインストールします。

   cd ~/webapp/python
   pipenv install newrelic
   

2. New Relicのライセンスキーを取得します。画面左下のユーザー設定から「API Keys」を選択し、「Create a key」から作成することができます。Key type にはIngest - Licenseを選択します。
   

3. newrelic.iniファイルを生成します。

   pipenv run newrelic-admin generate-config <YOUR_LICENSE_KEY> newrelic.ini
   

4. newrelic.iniファイルのapp_nameをisupipe（ISUCON13の題材アプリケーションの名前）などわかりやすい名前に変更しておきます。

   - app_name = 
   + app_name = isupipe
   

5. app.pyファイルの一番上に以下のようにコードを追記し、エージェントパッケージのインポート、エージェントを初期化する呼び出しを行います。

   + import newrelic.agent
   + newrelic.agent.initialize("newrelic.ini")
   + 
   import hashlib
   

6. ベンチマーカーを動かし、New Relicにデータが送られていることを確認します。

   cd ~
   ./bench run --enable-ssl
   

   うまくいけば、以下のように「APM & Services」に先ほどapp_nameに設定した名前のエンティティが現れます。（数分かかります）
   

Infrastructure Agentを入れる

「ISUCON 環境に New Relic Infrastructure Agent を入れてみる」を参考に進めます。
上記記事からの引用になりますが、こちらの手順を実施することで以下のような機能を利用することができます。

• ホスト単位あるいはプロセス単位でのCPU、メモリ、IOなどのメトリクス => Infrastructuer Agent
• MySQLの秒間クエリ数、接続数、スロークエリ数やインベントリ情報 => MySQL Integration
• ログの転送と分析 => Logs Integration　

1. 左のペインの「Integrations & Agents」からGuided installを選択します。

   

2. 「Auto-discovery」からLinuxを選択します。

   

3. User keyを新たに作成する場合は「Create a new key」でキーを生成、コピーしてから「Continue」で次に進みます。

   

4. インストールするためのコマンドが表示されるので、「Copy to clipboard」でコピーします。

   

5. EC2に接続されているターミナルに戻り、コピーしたコマンドをペーストして実行します。いくつかプロンプトに回答しインストールを進めます。
   

6. インストール完了後にNew Relicの画面に戻り「Continue
   」で次に進むと、インストール状況を確認することができます。

   

以上で準備が整いました！
次章から実際にチューニングしてみましょう

いざ、チューニング

まずはベンチを実行し、データを収集します。

実行が完了したら、「All Entities」から、先ほどの手順でInfrastructure Agentを入れたホストをクリックしてみます。

「Processes」を確認すると、ベンチマーカーのプロセスを除いて、mysqlプロセスのCPU使用率が最も高くなっていることが分かりました。

続いて、「APM & Services」の「Summary」を見てみます。
トランザクションタイムの大部分をMySQLが占めていることが分かりました。
まずはMySQL周りのチューニングをしていくことになりそうです。

続いて、「Transactions」を見ます。
「Sort by」 にはデフォルトで Most time consumingが指定されており、__main__:search_livestreams_handlerのトランザクションが最も時間を消費していることが分かります。

ここで、search_livestreams_handlerとは/api/livestream/searchエンドポイントに対応したPythonの関数名で、app.pyに書かれています。APMが勝手にエンドポイントごとにトランザクションタイムを集計してくれているのです。

__main__:search_livestreams_handlerをクリックすると、このトランザクションについてのより詳細なデータを確認することができます。

画面を下にスクロールすると、「Transaction traces」の欄にサンプリングされたトランザクションが表示されており、これをクリックします。（サンプリングされたトランザクションがない場合は、何度かベンチを実行すれば出てくるかと思います）

サンプリングされたトランザクションについて、より細かいデータを見ることができます。

「Database queries」を見ると一番上に表示されている以下のクエリにトータルで約10sかかっていることが分かりました。

SELECT * FROM livestream_tags WHERE livestream_id = %s

ターミナルに戻り、先ほどのクエリで使用されていたテーブルのインデックスを調べると、プライマリキーのインデックスしかないことが判明しました。

sudo mysql isupipe  # MySQLのisupipeデータベースに入る
SHOW INDEX FROM livestream_tags;  # インデックス情報を調べる

WHEREで絞り込みに使用されていたカラムにインデックスを張ります。

ALTER TABLE livestream_tags ADD INDEX idx_livestream_id (livestream_id);

再度ベンチを実行します。
トランザクションの詳細を見ると、先ほどは10sかかっていたクエリが2772msに改善されました

詳細は割愛しますが、同じ調子で他のテーブルにもインデックスを張っていきます。（「ISUCON13 問題の解説と講評」で追加するインデックスの例を見ることができます）

---

一通りインデックスを張り終えたところで、今度は Transactions の Sort by をSlowest average response timeに指定してみます。
すると、初期化処理を除くとmoderate_handlerの平均レスポンスタイムが最も遅いことが分かりました。

詳細を深ぼってみると、livecommentsテーブルへのDELETEが、1トランザクションあたり平均1.06k回走っており、これが処理時間の大半を占めていることが分かります。

該当のコードを見てみると、二重ループの中でクエリが実行されており、N+1問題が発生していました。

@app.route("/api/livestream/<int:livestream_id>/moderate", methods=["POST"])
def moderate_handler(livestream_id: int) -> tuple[dict[str, Any], int]:
    # ...
    
        # 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])

コードを修正してN+1問題を解消します。（参考までに、ChatGPTに書いてもらったコードを載せておきます）

修正後のコードを表示

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

        # NGワードにヒットする過去の投稿を一度のクエリで取得
        sql = """
            SELECT lc.*
            FROM livecomments lc
            INNER JOIN ng_words nw
            ON lc.livestream_id = nw.livestream_id
            WHERE nw.livestream_id = %s AND lc.comment LIKE CONCAT('%%', nw.word, '%%')
        """
        c.execute(sql, [livestream_id])
        rows = c.fetchall()

        if rows is None:
            raise HttpException("failed to get livecomments", INTERNAL_SERVER_ERROR)
        
        livecomment_ids_to_delete = [row['id'] for row in rows]

        # 一括削除
        if livecomment_ids_to_delete:
            sql = "DELETE FROM livecomments WHERE id IN (%s)" % (
                ",".join(["%s"] * len(livecomment_ids_to_delete))
            )
            c.execute(sql, livecomment_ids_to_delete)

        return asdict(models.ModerateResponse(word_id=word_id)), CREATED
    except DatabaseError as err:
        conn.rollback()
        raise err
    finally:
        conn.commit()
        conn.close()

再度計測すると、先ほどまではトップだったmoderate_handlerがずいぶん下に来ており、N+1問題が解消できていることも確認できました

New Relicを活用することで、ISUCONにおける代表的なチューニングであるインデックスの作成とN+1問題の解消を行うことができました。

改善できる余地はまだまだありそうですが、本記事でのチューニングは以上で終わりたいと思います。

まとめ

いかがだったでしょうか？

アプリケーションに New Relic を統合することの容易さと、問題分析のためのパワフルなUIを体験していただけたのではないかと思います！

10分程度で完了できるインストール作業を行うだけで、直感的でイカしたUIを利用でき、アプリケーションの問題点を発見することができました。

しかし、本記事で触れることができた New Relic の機能はほんの一部です。 モバイル・ブラウザ等のフロントエンドの観測、アラート通知、脆弱性管理などなど、New Relic にはオブザーバビリティのための機能がまだまだたくさん搭載されています。

本記事を読んでご興味を持たれた方はぜひ New Relic を触ってみてください！

参考にさせていただいた記事

• ISUCONの過去問にチャレンジするためのシンプルな環境構築
• matsuu/aws-isucon: ISUCON過去問をAWS環境で構築するための一式
• ISUCON13 当日マニュアル
• ISUCON13 問題の解説と講評
• New Relic フリープランで始めるオブザーバビリティ！ #初心者 - Qiita
• Install the Python agent
• ISUCON 環境に New Relic Infrastructure Agent を入れてみる

1. 「ISUCON」は、LINEヤフー株式会社の商標または登録商標です。：https://isucon.net ↩