Goアプリの中をのぞこう ​

アクセスログで「状態POSTとtrendを待っている」ことは分かりました。でも、その中で何がCPUを使ったかは分かりません。そこでGoに付属する**pprof（ピープロフ）**を使います。

pprofは、短い間隔で「今どの関数を実行しているか」と記録し、関数ごとのCPU時間を集計するprofiler（プロファイラー）です。アプリの中へ入って、仕事の内訳を見られます。

最初はflatとcum ​

• flat: その関数自身の中で使ったCPU時間
• cum: その関数から呼び出した先も含めたCPU時間

たとえば、getTrend自身のflatが小さくても、その中から呼んだSQLやJSON変換を含むcumが大きければ、trend処理全体が候補です。最初はcumの大きい、自分たちが書いた関数を探すと読みやすいでしょう。

runtimeやsyscallという名前もたくさん出ます。これはGoやOSの土台の処理です。いきなり土台を書き換えようとせず、そこへつながる自分たちの関数をたどります。

Agentへのプロンプト ​

次はGoアプリへpprofを導入し、CPU profileを根拠に改善してください。

- Goのversionと起動方法を確認する
- pprofは外部公開せず、127.0.0.1の専用portだけで待ち受ける
- service再起動後、サーバー内からpprofの一覧が開けることを確認する
- ベンチの負荷時間全体を含むCPU profileを同時に取得する
- go tool pprofのtopをflat順とcum順で確認する
- runtimeやsyscallだけで結論を出さず、自分たちのhandlerまで呼び出し元をたどる
- 上位の処理、時間、全体に占める割合を記録する
- 観測とつながる変更を入れ、ベンチとpprofをもう一度取る
- profile本体はGit管理せず、判断に使った数値だけを残す

pprofを有効にするための変更と、そこから導いた高速化の変更を分けて説明してください。

次はGoアプリへpprofを導入し、CPU profileを根拠に改善してください。

- Goのversionと起動方法を確認する
- pprofは外部公開せず、127.0.0.1の専用portだけで待ち受ける
- service再起動後、サーバー内からpprofの一覧が開けることを確認する
- ベンチの負荷時間全体を含むCPU profileを同時に取得する
- go tool pprofのtopをflat順とcum順で確認する
- runtimeやsyscallだけで結論を出さず、自分たちのhandlerまで呼び出し元をたどる
- 上位の処理、時間、全体に占める割合を記録する
- 観測とつながる変更を入れ、ベンチとpprofをもう一度取る
- profile本体はGit管理せず、判断に使った数値だけを残す

pprofを有効にするための変更と、そこから導いた高速化の変更を分けて説明してください。

1回目のprofile ​

ベンチと同時に70秒のCPU profileを取りました。スコアは21,710です。計測前より上がっていますが、まだコードは変えていません。ベンチの揺れもあるので、pprofを入れただけの点数アップとは扱いません。

cum時間で目立ったものは次のとおりです。

特に面白いのはログと字下げです。利用者へ必要な仕事ではありません。アクセスログはnginx側にもうあり、捨てるPOSTの事実も7万行の警告にする必要はありません。JSONの空白や改行も、ブラウザが読む内容を変えません。

計測のための仕事を減らす ​

次をまとめて変更しました。

• Go側の全request loggerを外す
• 捨てた状態POSTごとの警告を外す
• Echoのdebug modeを止め、JSONを小さく返す
• エラーのログは残す

スコアは24,516へ上がりました。もう一度pprofを見ると、Warnfとjson.Indentは上位から消えています。「ログを消したら速そう」ではなく、消す前と後のprofileで確認できました。

次に見えたgetTrend ​

2回目のpprofではgetTrendが2.42秒で上位でした。アクセスログでも1分に約1万回呼ばれています。公式仕様では、状態の反映を短時間遅らせることが許されています。

そこで、trendのJSONを500msだけ再利用しました。同時に期限切れになっても、最初の1リクエストだけが再計算し、ほかはその結果を待ちます。初期化とISU登録時にはcacheを捨てます。

時間は約5分の1になりましたが、スコアは横ばいでした。それでも次のpprofではgetTrendが上位から消えています。変更は狙いどおり効き、全体の上限が別の場所へ移った、と判断できます。

スコアが毎回きれいに上がるとは限りません。profileの山を消せたかと、サービス全体のスコアが伸びたかは、両方を記録しましょう。