こんにちはマネージドサービス部 大城です。
前回のブログ の続きを書きます。今回は Python で試してみます。
New Relic APM をインストールした後、ボトルネックがどこにあるのか確認して、少しだけチューニングします。
前準備
前回のブログ を参考に Python にNew Relic APMを入れます。
t3 などのバースト型のインスタンスを使うとスコアが安定しなかったので、今回は c6a.xlarge で進めました。
やってみた
チューニングなしの状態
環境ができたらチューニングなしで一度ベンチマークを走らせてみます。
ベンチマーク１回目
チューニングなし状態のスコアは 2986 でした。
ベンチマーク１回目 スコア: 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
ベンチマーク２回目
index作成後の スコアは 3268 でした。少し上がりました。
ベンチマーク２回目 スコア: 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を作成するとスコアが良くなりそうですが、次のチューニングを試してみます。
N+1(エヌプラスワン)問題の解消
N+1問題とは、1つの親オブジェクトに対して、子オブジェクトの数だけ別々のクエリを発行してしまう問題のことです。
参考記事
New Relicのトレース画面を見ていると明らかにN+1の動きをしているトランザクションがあったので確認してみます
moderate_handler 関数のトレース画面で delete が1991回実行されていることがわかります。これはワンクリックでdelete が1991回実行されていることを表しています。
また画面下の Transaction trace でも delete が大量にあることがわかります。delete処理がチリツモになって処理時間が延びています。
ソースコードを普段書かない私が直すと日が暮れそうなので 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
ベンチマーク３回目
少しだけ良くなりましたが、あまりスコアは変わらず 3277 でした。
ベンチマーク３回目 スコア: 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 （緑部分）が大幅に減ったことがわかります。
このあたりで今回は切り上げます。いろいろやっていると楽しいので、無限に時間が溶けてしまいます。
参考
ボトルネックはどこから手を付ければよいか
ケースによるので、明確な答えはないのですが参考として書きます。ボトルネックは大きいもの（支配的なもの）から対応したほうが解消が早いです。
支配的なリクエストを切り分ける際の参考として 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
