2日で作ったサービスの技術負債を、運用しながら改善する

運用中の発音矯正サービスは、2日で作ったPoCから始まりました。運営メンバーを説得する必要があり、市場が反応するかを早く確かめる必要があったからです。AIと共にスピードを優先して積み上げ、その選択のおかげでクローズドベータとテスター募集を経て、ベータサービスまで来ました。

技術負債は運用に入ると現象として現れました。「ログインが遅い気がします」「D1が遅いからAWSへ移すべきでは?」「使う人がいない時間なのにトラフィックが出ます」といった報告です。エラーログはありません。すべて正常なレスポンスで、ただ遅いだけなのか、よくわからず何かがおかしいだろうなという推測のみが残ります。デバッグのための手がかりが明確にない状態で、調査を始めるしかありませんでした。

ベータ環境にwrangler tailを仕掛け、リクエストごとにwallTimeとcpuTimeを記録しました。演算は少ないのに全体の時間だけ長いなら、コードが遅いのではなく何かを待っているという意味です。

wrangler tail: デプロイされたCloudflare Workersのリクエストログをターミナルでリアルタイムに眺めるコマンド。リクエストごとにwallTime(応答までの全体時間)とcpuTime(そのうち実際の演算に使った時間)が一緒に残ります。

決定的な手がかりはセッション照会でした。全体で573msかかるのに、実際の演算は11msしかありませんでした。残りの562msは何かを待つ時間で、その正体はセッションを速くするために入れておいたKVキャッシュでした。

測定で特定した原因は4つで、4つとも初期にスピードのために入ったコードでした。

ひとつ目は、セッションキャッシュとして使っていたKVです。最初はセッション照会を減らすために入れましたが、結果整合性のためセッション状態の反映が遅れていることがわかりました。この遅延は20分ごとにログインが切れるバグにつながり、セッションの正式な保存先は最終的にD1へ移しました。その後の測定では、KVを経由する経路自体が性能を落としていたため、残っていたキャッシュ層も外しました。

ギャラリーの照会も、必要なデータよりはるかに多くのデータを読んでいました。カードに必要なのは画像アドレスだけなのに、クエリはレガシーのキャンバスデータを含むレコード全体を取得していました。カード519枚の先生ユーザーのアカウントではレスポンスサイズが6.64MBに達し、その97%は画面で使われないデータでした。セッション情報の準備前にクエリが走るため同じリクエストが再発し、リクエスト内でセッション照会を共有していなかったため、ひとつの画面でセッション照会が5回繰り返されていました。

ひとつずつ外し、まとめた結果です。

「使う人がいない時間にトラフィックが出る」という報告は、5分間に入ってくるリクエストをそのまま書き取ることで確認しました。5分間のリクエストは6件、すべて同じ出どころでした。Sentryのアップタイム監視ボットが正確に60秒間隔でランディングページを呼んでおり、生存確認のたびにページ全体をサーバーレンダリングさせていました。1日1,440回です。同じ5分間、実ユーザーのリクエストは0件でした。軽量なヘルスチェックのエンドポイントを作り、ボットをそちらへ向けました。

早朝のトラフィックスパイクはボットではありませんでした。時間帯別の活動記録を数えると、朝7時台に課題の提出が集中していました。提出1件はリクエスト1件ではありません。文の数だけ音声ファイルがアップロードされ、ワークフローが続きます。チームには「使う時間じゃない」時間帯が、学生には登校前の準備時間でした。

「D1が遅いからAWSへ移すべきか」という質問への答えは、D1クエリは最初から45~96msで正常であり、問題はその手前に積まれたキャッシュ層と呼び出しパターンだということでした。インフラの移行は不要でした。

速く作ったこと自体を後悔してはいません。あのスピードがなければ説得もベータもなかったはずです。ただ、速く積んだコードには運営で実測しながら見直す手順が伴うべきで、その手順の入力はwallTimeとcpuTimeのような数字であるべきです。今回の調査で得たルールです。まだ残っている負債もあります。演算が重いプロシージャひとつと、30秒ポーリングの見直しが次の番です。