Webアプリの入口を見渡そう ​

スロークエリログで、データベースの大渋滞はかなり解消できました。次は視点を一歩引いて、nginxの**access log（アクセスログ）**を見ます。

nginxは、ブラウザから来たリクエストを最初に受け取る案内係です。アクセスログには、どのURLが何回呼ばれ、返すまで何秒かかり、何byte送ったかを残せます。データベースを使わない処理も含めて、サービス全体を同じ物差しで比べられます。

今回見る数字 ​

• COUNT: そのURLが呼ばれた回数
• SUM: 全リクエストの待ち時間を足した値
• AVG: 1回あたりの平均時間
• P90、P99: 遅いほうから10%、1%付近の時間
• SUM(BODY): 送ったデータ量の合計

平均だけを見ると、ごく一部の遅いリクエストを見落とします。反対に最大値だけを見ると、たまたま一度だけ遅かったものに振り回されます。回数、合計、平均、遅い側の値を並べて眺めましょう。

Agentへのプロンプト ​

次はnginxのaccess logを導入し、その情報だけから説明できる改善をしてください。

- 現在読み込まれているnginx設定と既存ログ形式を確認する
- method、URI、status、response bodyのbyte数、request_time、upstream_response_timeを1行JSONで記録する
- nginx -tで設定を検証してからreloadし、実際の1行がJSONとして読めることを確認する
- 集計ツールは既存のものを探し、必要なら公式配布元からchecksumを検証して導入する
- ベンチ前にaccess logを空にする
- UUIDやquery parameterの違いをまとめ、URLの役割ごとに集計する
- COUNT、SUM、AVG、P90、P99、SUM(BODY)を比較する
- まず変更前を計測し、観測と直接つながる変更だけを入れ、もう一度計測する
- status codeとレスポンス内容を壊していないか確認する
- スコアと、変更前後の回数・時間・転送量を記録する

ログだけでは原因を断定できないものは、推測で直さず「pprofで調べる候補」として残してください。

次はnginxのaccess logを導入し、その情報だけから説明できる改善をしてください。

- 現在読み込まれているnginx設定と既存ログ形式を確認する
- method、URI、status、response bodyのbyte数、request_time、upstream_response_timeを1行JSONで記録する
- nginx -tで設定を検証してからreloadし、実際の1行がJSONとして読めることを確認する
- 集計ツールは既存のものを探し、必要なら公式配布元からchecksumを検証して導入する
- ベンチ前にaccess logを空にする
- UUIDやquery parameterの違いをまとめ、URLの役割ごとに集計する
- COUNT、SUM、AVG、P90、P99、SUM(BODY)を比較する
- まず変更前を計測し、観測と直接つながる変更だけを入れ、もう一度計測する
- status codeとレスポンス内容を壊していないか確認する
- スコアと、変更前後の回数・時間・転送量を記録する

ログだけでは原因を断定できないものは、推測で直さず「pprofで調べる候補」として残してください。

今回のAgentは、アクセスログ集計ツールalpを公式リリースから導入しました。alpは、同じ役目のURLをまとめ、上の数字を表にしてくれます。ISUのUUIDが違うURLをそのまま数えると別々の行になるため、/api/isu/<UUID>/iconのようにまとめる設定も大切です。

入口から見えたもの ​

最初のアクセスログ計測は18,812でした。合計待ち時間順に並べると、上位はこうなりました。

状態POSTが圧倒的です。ただし、アクセスログから分かるのは「入口から出口まで待った」ことだけ。Goのどの処理が時間を使ったかはまだ分かりません。これはpprofで調べる候補に残しました。

一方、JavaScriptやCSSは、ベンチ中に内容が変わりません。それなのにGoアプリを通してファイルを読んでいます。ここはアクセスログだけでも、仕事を減らせる理由がはっきりしています。

静的ファイルはnginxへ ​

JavaScript、CSS、SVGとindex.htmlを、nginxから直接返すようにしました。変更前後でファイルのハッシュが同じことも確認しています。さらに、変わらないassetには1時間の有効期限を付けました。

再計測は19,628。assetの待ち時間は集計上0.000秒になりました。面白いのは、状態POSTのコードを変えていないのに平均が27msから11msへ下がったことです。同じサーバーのGoアプリが静的ファイルを返さなくなり、本来のAPIへCPUを使えるようになったためだと考えられます。

次は、大きな画像を送らない ​

再計測したアクセスログでは、ISUのアイコンが4,763回、117MB送られていました。アイコンは登録後に変更するAPIがなく、同じ利用者へ同じ画像を何度も返しています。

そこで、認証が必要な画像であることを保つためprivateなCache-ControlとETagを付けました。サーバー全体で他人と共有するcacheにはしていません。

約4分の1まで減り、スコアも伸びました。これでアクセスログから素直に選べる変更は一区切りです。残った最大の山、状態POSTの中身をpprofでのぞきに行きましょう。