Private-ISUのスコアが101倍までのパフォーマンス改善記録

目次

初期状態

  • スコア: 2,287

1回目のコミット: 削除フラグによる絞り込み最適化とインデックス

投稿を取得するSELECT文を修正し、削除フラグ(del_flg)が立っていないアクティブなユーザーの投稿のみを対象とするように変更しました。合わせて、この絞り込み処理を高速化するため、関連するカラムにインデックスを追加しました。

スコア

  • 2,287 → 22,381 (約10倍向上)

2回目のコミット: クエリ改善とDB接続安定化

1回目のクエリ改善を他の箇所にも適用しました。加えて、データベース接続の安定性を向上させるため、起動時の接続リトライ処理とコネクションプールの設定(最大接続数、アイドル接続数など)を追加しました。さらに、クライアントサイドでSQLのパラメータを展開するinterpolateParams=trueオプションを有効にし、オーバーヘッドを削減しました。

スコア

  • 22,381 → 35,266 (約1.6倍向上)

3回目のコミット: MySQLのアップグレードとクエリ最適化

3回目のコミットでは、まずMySQLのバージョンを8.4から9.1に更新しました。次にEXPLAINで実行計画を分析したところ、usersテーブルが先にスキャンされ、インデックスが有効活用されていないことが判明しました。そこで、JOINSTRAIGHT_JOINに変更してテーブル結合順序を固定しました。

スコア

  • 35,266 → 41,489 (約1.2倍向上)

4回目のコミット: 画像配信の最適化とNginxによるキャッシュ

これまでデータベースから直接配信していた画像を、初回アクセス時にファイルとして保存する仕組みを導入しました。Nginxの設定を変更し、リクエストされた画像がファイルとして存在する場合は、アプリケーションサーバーを介さずに直接配信するようにしました。これにより、画像アクセスのたびにデータベースやアプリケーションに負荷がかかるのを防ぎ、レスポンスを大幅に高速化しました。

スコア

  • 41,489 → 85,838 (約2.1倍向上)

5回目のコミット: DB接続プールの最適化とpprofによる効果測定

前回までの修正でスコアが大幅に向上したため、pprofを用いてCPUプロファイリングを実施し、次なるボトルネックの特定を行いました。分析の結果、DB接続周りの処理に改善の余地があると考え、接続プールの設定を最適化しました。

pprofによるパフォーマンス分析

DB接続プール設定の最適化前後のCPUプロファイル(top -cum)を比較します。

修正前のCPU使用率トップ5

Duration: 60s, Total samples = 35.73s (59.55%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 23.21s 64.96%
main.makePosts 14.46s 40.47%
internal/runtime/syscall.Syscall6 13.09s 36.64%
database/sql.withLock 12.83s 35.91%
database/sql.(*DB).QueryContext 12.82s 35.88%
修正後のCPU使用率トップ5

Duration: 60.01s, Total samples = 31.98s (53.29%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.63s 67.64%
main.makePosts 13.61s 42.56%
database/sql.(*DB).retry 12.31s 38.49%
database/sql.withLock 12.17s 38.06%
database/sql.(*DB).QueryContext 12.05s 37.68%
分析と考察


総サンプル時間は 35.73s から 31.98s へと約10%減少しました。これはアプリケーション全体のCPU負荷が軽減されたことを示しています。
しかし、DB接続のロックに関連する database/sql.withLock のCPU全体に占める割合は 35.91% から 38.06% へと微増しました。このことから、接続プールの設定変更は一定の効果があったものの、依然として接続時の競合がパフォーマンスに影響を与えている可能性が考えられます。
また、修正後のプロファイルで、database/sql.(*DB).retry がトップ5に出現しました。これは修正前から存在していた問題でしたが、internal/runtime/syscall.Syscall6の負荷軽減により相対的に可視化されたものです。driver.ErrBadConn が発生し、データベースドライバの内部で接続リトライが頻発していることを示しています。
原因として、Goアプリケーション側で設定した ConnMaxLifetimeConnMaxIdleTime と、MySQLサーバーやプロキシ(存在する場合)のタイムアウト設定との間に不整合がある可能性が高いと考えられます。これにより、アプリケーションがプールから取得した接続が、サーバー側ですでに切断されているという状況が発生していると推測されます。

結論と次のステップ

DB接続プールの調整により、スコアは 85,838 から 90,449 へと約5%向上しました。しかし、CPUプロファイル分析から、期待していたDB接続競合の大幅な緩和には至っていないことが分かりました。
むしろ、今回の最適化によってDB.retryという、これまで潜在していた接続リトライの問題が顕在化しました。これは接続タイムアウト設定の不整合が原因と推測されます。
また、プロファイル結果は、依然としてアプリケーション全体の最大のボトルネックが main.makePosts 関数内のN+1問題であることを明確に示していました。

スコア

  • 85,838 → 90,449 (約1.05倍向上)

補足検証: getPostsクエリ実行計画の比較分析

3回目のコミットでSTRAIGHT_JOINを導入しましたが、その際はFORCE INDEXとの比較を行っていませんでした。N+1問題という大きな改善に取り組む前に、getPostsのクエリが本当に最適化されているかを確認するため、改めてJOIN(オプティマイザ任せ)とSTRAIGHT_JOINおよびFORCE INDEX(ヒント句による強制)の3パターンを比較検証することにしました。

検証結果
最適化手法 実行時間 改善率(vs 通常JOIN) スキャン行数
通常のJOIN 13.4ms - 9,790行
FORCE INDEX 0.104ms 129倍 22行
STRAIGHT_JOIN 0.0778ms 172倍 22行
分析と考察

通常のJOINでは、オプティマイザがusersテーブルを起点とする非効率な実行計画を選択し、9,790行の中間結果を生成していました。STRAIGHT_JOINFORCE INDEXは、postsテーブルのインデックスを起点とする計画を強制してスキャン行数を22行に抑え、それぞれ172倍、129倍の大幅な高速化を達成しました。両者を比較し、最も高速だったSTRAIGHT_JOINのアプローチが最適であると最終的に判断しました。

6回目のコミット: N+1問題の解消

getPostsの最適化手法を確定させた後、最大のボトルネックであったmain.makePosts関数内のN+1問題の解消に取り組みました。

pprofによるパフォーマンス分析

N+1問題修正前後のCPUプロファイル(top -cum)を比較します。

修正前のCPU使用率トップ5

Duration: 60.01s, Total samples = 31.98s (53.29%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.63s 67.64%
main.makePosts 13.61s 42.56%
database/sql.(*DB).retry 12.31s 38.49%
database/sql.withLock 12.17s 38.06%
database/sql.(*DB).QueryContext 12.05s 37.68%
修正後のCPU使用率トップ5

Duration: 60.11s, Total samples = 31.48s (52.37%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 23.36s 74.21%
html/template.(*Template).Execute 9.30s 29.54%
main.getIndex 9.03s 28.68%
internal/runtime/syscall.Syscall6 7.53s 23.92%
jmoiron/sqlx.(*DB).Select 6.14s 19.50%
分析と考察

修正前のプロファイルで上位を占めていたmain.makePostsdatabase/sql.withLockといったDB関連の関数がtop -cumから姿を消しました。これにより、N+1問題が解消され、DB負荷が大幅に軽減されたことが定量的に確認できます。
DB負荷の軽減に伴い、これまで潜在化していたhtml/template.(*Template).Execute (29.54%) が新たなボトルネックとして顕在化しました。これはサーバーサイドでのHTMLレンダリング処理にCPU時間が費やされていることを示しています。

結論と次のステップ

N+1問題の解消は成功し、スコアは 90,449 から 191,302 へと約2.1倍向上しました。CPUプロファイル分析により、HTMLのテンプレートレンダリング処理が新たなボトルネックであることが明確になりました。

スコア

  • 90,449 → 191,302 (約2.1倍向上)

7回目のコミット: HTMLテンプレートの最適化

6回目のコミットで明らかになったHTMLテンプレートのレンダリング処理のボトルネックを解消するため、テンプレートの事前コンパイルや構造の見直しを行いました。

pprofによるパフォーマンス分析

最適化前後のCPUプロファイル(top -cum)を比較します。

修正前のCPU使用率トップ5

Duration: 60.11s, Total samples = 31.48s (52.37%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 23.36s 74.21%
html/template.(*Template).Execute 9.30s 29.54%
main.getIndex 9.03s 28.68%
internal/runtime/syscall.Syscall6 7.53s 23.92%
jmoiron/sqlx.(*DB).Select 6.14s 19.50%
修正後のCPU使用率トップ5

Duration: 60.19s, Total samples = 29.69s (49.33%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.91s 73.80%
go-chi/chi/v5.(*Mux).ServeHTTP 19.84s 66.82%
internal/runtime/syscall.Syscall6 8.15s 27.45%
html/template.(*Template).ExecuteTemplate 7.97s 26.84%
main.getIndex 7.28s 24.52%
分析と考察

テンプレート最適化により、主要なボトルネックであったhtml/template.(*Template).ExecuteのCPU時間は9.30sから7.97sへと約14%削減されました。アプリケーション全体のCPU負荷も、総サンプル時間が31.48sから29.69sへと約6%軽減され、改善が見られます。

しかし、依然としてテンプレート関連の処理(html/template.(*Template).ExecuteTemplate)は上位に残っています。また、internal/runtime/syscall.Syscall6が高い割合(27.45%)を示しており、システムコールレベルでのオーバーヘッドが大きいことがうかがえます。これはファイルI/Oやネットワーク通信などが影響していると考えられます。

結論と次のステップ

テンプレートを起動時に一括コンパイルするよう変更し、リクエスト毎のパース処理をなくしたことでオーバーヘッドを解消しました。この最適化により、スコアは 191,302 から 202,674 へと約1.06倍向上しました。
しかし、依然としてテンプレートの描画処理(ExecuteTemplate)とコメント取得のクエリがCPU時間の上位を占めていました。特に投稿一覧では、コメントを全件取得してから3件に絞り込む非効率な処理が残っていました。

スコア

  • 191,302 → 202,674 (約1.06倍向上)

8回目のコミット: コメントSQL最適化とTEMPLATE負荷軽減のためのMemcached導入の見送り

7回目のコミットで明らかになったHTMLテンプレートのレンダリング処理とコメント取得クエリのボトルネックを解消するため、コメント取得SQLの最適化と、Memcachedを利用したHTMLキャッシュ基盤の実装を行いました。
ただし、HTMLキャッシュについては、有効化すると逆にスコアが悪化することが実験で判明したため、テンプレート側での呼び出しは行っておらず、現状ではキャッシュ機能は無効化された状態です。

pprofによるパフォーマンス分析

最適化前後のCPUプロファイル(top -cum)を比較します。

修正前のCPU使用率トップ5

Duration: 60.19s, Total samples = 29.69s (49.33%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.91s 73.80%
go-chi/chi/v5.(*Mux).ServeHTTP 19.84s 66.82%
internal/runtime/syscall.Syscall6 8.15s 27.45%
html/template.(*Template).ExecuteTemplate 7.97s 26.84%
main.getIndex 7.28s 24.52%
修正後のCPU使用率トップ5

Duration: 60s, Total samples = 28.07s (46.78%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.09s 75.13%
go-chi/chi/v5.(*Mux).ServeHTTP 19.49s 69.43%
html/template.(*Template).ExecuteTemplate 9.25s 32.95%
text/template.(*state).walk 9.23s 32.88%
main.getIndex 8.34s 29.71%
分析と考察

総サンプル時間は 29.69s から 28.07s へと約5.4%減少し、アプリケーション全体のCPU負荷が軽減されました。これは主に、投稿一覧ページにおけるコメント取得SQLを最適化し、ウィンドウ関数を用いて最新3件のみを取得するように変更した効果です。
一方で、html/template.(*Template).ExecuteTemplate の累積時間は 7.97s から 9.25s へと増加しています。これは、実装したHTMLキャッシュ機能がテンプレート側で呼び出されていないため、キャッシュが一切機能せず、テンプレート描画のコストがそのまま計上されているためです。

結論と次のステップ

今回のスコア向上(202,674221,685)は、コメントSQLの最適化によるものと結論付けられます。
実装したHTMLキャッシュ基盤については、テンプレートから呼び出すように変更して検証したところ、スコアが 143,374 へと大幅に悪化しました。これは、ベンチマーク環境におけるキャッシュヒット率の低さや、Memcachedとの通信オーバーヘッドが、テンプレート描画処理の削減効果を上回ってしまったためと推測されます。
この結果から、現状のアーキテクチャではHTMLキャッシュは逆効果であると判断し、採用を見送りました。

スコア

  • 202,674 → 221,685 (約1.09倍向上)

9回目のコミット: Nginxの最適化

8回目のコミットでアプリケーション内部の主要なボトルネックは解消されたため、Webサーバー/リバースプロキシ層の最適化に着手しました。Nginxの設定を全面的に見直し、静的コンテンツの配信効率とバックエンドアプリケーションとの通信効率を向上させました。

pprofによるパフォーマンス分析

最適化前後のCPUプロファイル(top -cum)を比較します。

修正前のCPU使用率トップ5

Duration: 60s, Total samples = 28.07s (46.78%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.09s 75.13%
go-chi/chi/v5.(*Mux).ServeHTTP 19.49s 69.43%
html/template.(*Template).ExecuteTemplate 9.25s 32.95%
text/template.(*state).walk 9.23s 32.88%
main.getIndex 8.34s 29.71%
修正後のCPU使用率トップ5

Duration: 60.11s, Total samples = 28.23s (46.97%)

関数 累積時間 (cum) 割合
net/http.(*conn).serve 21.65s 76.69%
go-chi/chi/v5.(*Mux).ServeHTTP 20.19s 71.52%
html/template.(*Template).ExecuteTemplate 8.96s 31.74%
text/template.(*state).walk 8.96s 31.74%
main.getIndex 8.11s 28.73%
分析と考察

総サンプル時間は 28.07s から 28.23s へとほぼ横ばいで、Goアプリケーション自体のCPUプロファイルに大きな変化は見られません。これは、今回の最適化がアプリケーションの前段にあるNginxレイヤーで行われたためで、想定通りの結果です。スコアが向上した要因は、pprofには直接現れないNginxの動作改善にあります。具体的には、upstreamでのKeepalive接続有効化によるNginx-Go間の通信効率向上、sendfileopen_file_cacheによるOSレベルでの静的ファイル配信の高速化、そしてCSS/JSへのCache-Controlヘッダ付与によるブラウザキャッシュの活用です。これらの地道なインフラ層の改善がシステム全体のスループットを底上げし、スコア向上に繋がったと分析できます。

結論

今回のスコア向上(221,685232,039)は、Nginxのインフラ層のチューニングによるものと結論付けられます。
pprofの結果から、アプリケーションのボトルネックは依然として html/template のレンダリング処理であることがわかりました。

スコア

  • 221,685 → 232,039 (約1.05倍向上)
Graph
Image in a image block
Flame Graph
Image in a image block

全体のスコア推移まとめ

コミット スコア 前回比
初期状態 2,287 -
1回目 22,381 x9.8
2回目 35,266 x1.6
3回目 41,489 x1.2
4回目 85,838 x2.1
5回目 90,449 x1.05
6回目 191,302 x2.1
7回目 202,674 x1.06
8回目 221,685 x1.09
9回目 232,039 x1.05

9回目のコミットで初期スコアから101倍になったので終わり!!

総合スコア 2,287 → 232,039 (約101倍向上)

目次