Language: 日本語

「どこが遅いかわからない」から始める性能改善。勘を捨てて Cloud Trace の事実から入るアプローチ

「Web アプリのレスポンスが全体的に遅い……でも、具体的にどこが詰まっているのかわからない」

エンジニアなら誰しも一度は頭を抱えたことがあるのではないでしょうか？

とりあえず怪しそうな SQL にインデックスを貼ってみたり、フロントエンドで安易に prefetch を増やしてみたり。「たぶんここが重いんだろう」という 「勘のチューニング」 で時間を溶かしてしまった経験はありませんか？

私がアノテーション基盤の性能改善に参画したときも、まさに「タスク取得に 2 秒以上待たされる」「全体的に遅い」という課題からスタートしました。当初チーム内で挙がっていた仮説も「インデックス不足」や「フロントのキャッシュ」でした。

しかし、直す場所を決めつけずに OpenTelemetry と Cloud Trace による分散トレースを導入したところ、遅延の真犯人はまったく別の 3 つのレイヤ（Node.js タイマー、外部認証通信、DB トランザクション境界）に隠れていたのです。

この記事では、勘を完全に捨ててトレースの事実からボトルネックを特定し、21 エンドポイントの p50 レスポンスタイムを 16,310ms から 127ms（約 128 倍高速化）へ改善したプロセス をまとめます。

得られること

「勘で直す」罠を回避し、分散トレース（OpenTelemetry / Cloud Trace）で真のボトルネックを特定するフローがわかる
ランタイム・外部 I/O・DB トランザクションという複数レイヤに散らばった原因の解剖例が学べる
単発のログではなく「固定条件 20 周ベンチマーク」で 128 倍の改善を客観的に証明する検証体制が身につく！

勘を捨ててログとスパンから始める改善サイクル

性能改善で最もやってはいけないのは、「最初から直す場所を決めてかかること」 です。

今回効果を発揮したのは、以下のような「事実から入る」シンプルなサイクルでした。

OpenTelemetry のトレース / ログを収集
    ↓
異常な所要時間や不自然な呼び出し回数を「Finding」として抽出
    ↓
スパンの内訳から原因の仮説を立てる
    ↓
コードや実行計画（EXPLAIN）を確認して修正
    ↓
同じ固定条件で再計測して効果を検証 ⚡️

「インデックスを貼ろう」「prefetch しよう」から入っていたら、これから紹介する根本原因には絶対に辿り着けませんでした。

Cloud Trace が暴いた 2.46 秒の真実

まず最初に行ったのは、Frontend と Backend（Cloud Run）に OpenTelemetry を仕込み、同一の Trace ID でリクエストを串刺しにして Cloud Trace へ流すことでした。

遅いとされていた GET /api/tasks/next のトレースを開いてみると、全体で 2.46 秒 かかっていました。みなさんなら、この 2.46 秒の内訳がどこにあると予想しますか？

実際のトレースの内訳がこちらです。

スパン名	実際の所要時間
`SELECT`（DB クエリ本体）	3〜16 ms ⚡️
`transaction`（トランザクション全体）	377 ms
`BEGIN`（トランザクション開始）	177〜211 ms 💥

これを見た瞬間、目から鱗が落ちました。 「DB の SELECT クエリ自体はたったの 3ms で爆速で終わっていた」 のです。

待ち時間の正体は、クエリ本体ではなく 「RLS（Row Level Security）のユーザーコンテキストを設定するトランザクション境界（BEGIN / 接続ハンドシェイク）」 でした。

【Before のトレース内訳】
全体: 2.46s
├── BEGIN / トランザクション開始待ち: 177〜211ms 💥
├── トランザクション処理: 377ms
└── SELECT クエリ本体: 3〜16ms（実は一瞬で終わっていた！）

この事実がわかったことで、探すべき対象は「重い SQL」ではなく「トランザクション境界のオーバーヘッド」へと一気に絞り込まれました。

改善後に同じエンドポイントのトレースを再取得したところ、リクエスト全体は 2.46 秒から 309ms（約 8 倍高速化） に縮み、BEGIN も 2〜3ms に収まるようになりました。

異なる 3 つのレイヤで見つかった根本原因

トレースとログを手がかりに掘り下げていくと、まったく異なる 3 つのレイヤにボトルネックが散らばっていました。

【1. ランタイム層（Node.js）】
  ・Node.js の setTimeout / setInterval に 720 時間を渡して TIMEOUT_MAX を超過
  ・1ms に切り詰められて毎秒 1,000 回マスターデータを再読込していた（記事 01）
      ↓
【2. 認証・外部通信層】
  ・Firebase Auth の verifyIdToken で checkRevoked=true を毎リクエスト同期実行
  ・毎回 Google の外部エンドポイントへ通信して 217ms 待たされていた（記事 02）
      ↓
【3. データベース層（PostgreSQL）】
  ・RLS ポリシーに関数の引数として行のカラムを渡していた
  ・スキャン行数 N に比例して認可関数が N 回ループ実行されていた（記事 03）

ランタイムのタイマー、外部 API への HTTP 通信、DB のポリシー評価。どれも 「遅い SQL を探す」「フロントを prefetch する」というアプローチでは 1 つも見つけられなかったものばかり です。

「トレースで異常なスパンを見つけ、そのレイヤへ潜る」というアプローチを徹底したからこそ、見当違いな修正をせずに済みました。

21 エンドポイントでの固定条件 20 周ベンチマーク

局所的な改善でも「Task 一覧が 130ms → 0.159ms」「Work history が 4,689ms → 0.054ms」といった劇的な数値が出ました。しかし、局所的な測定だけでは「アプリ全体として本当に体験が改善したのか」はわかりません。

そこで、同一条件（1 プロジェクト、100 リクエスト、10,000 タスク）の検証環境を構築し、全 21 エンドポイントを 20 周実行して p50（中央値）と p95 を計測 しました。

指標（21 エンドポイント）	Before（改善前）	After（改善後）	改善率
p50 中央値	16,310 ms	127 ms	約 128 倍 ⚡️
p95 中央値	22,329 ms	367 ms	約 61 倍 ⚡️
最大改善エンドポイント	31,467 ms	97 ms	322.9 倍（Task label summary）

成功レスポンス（2xx）のみを対象にした平均値でも、p50 は 20,381ms → 176ms、p95 は 27,078ms → 441ms と、ほぼすべての操作が 1 秒未満で完結するようになりました。

利用者の体験はどう変わったのか

このミリ秒単位の数字を、実際のユーザーの操作フローに戻してみます。

利用者	代表的な操作	p50 の変化	実際の体験の変化
アノテーター（作業者）	Task 詳細画面の表示 Annotation 履歴の取得	25,721ms → 205ms 15,813ms → 154ms	タスクを開いて確認するたびに作業のリズムが途切れなくなった
依頼者（Requester）	プロジェクト統計の確認タスク完了状況の一覧	22,514ms → 224ms 9,107ms → 105ms	進捗確認が「待たされる作業」ではなくなり、即座に次の判断へ移れる
管理者（Operator）	プリセット設定の一覧プロジェクトメンバー一覧	17,580ms → 88ms 27,555ms → 118ms	設定変更と確認のイテレーションをその場でストレスなく回せる

※ これはユーザー調査による生産性の実測ではなく、再現ベンチマークから導いた操作レスポンスの変化です。

Observability とエージェントの自律的な探索

パフォーマンス改善において最もコストが高いのは、「見当違いな場所をいじって時間を溶かすこと」です。

これは人間だけでなく、コーディングエージェントにもまったく同じことが言えます。AI に「なんか重いから速くして」とだけ指示しても、実行時の事実がなければプログラミングの膨大な変数の中で勘に頼るしかなく、表面的なキャッシュや prefetch を足してコードを複雑にしがちです。

ここで重要なのは、「人間が全部ログを見て、人間が直す場所を指示する」ことではありません。

そうではなく、「AI 自身が Cloud Trace のスパンやログを探索し、豊富な実行時コンテキストを直接取得できるように観測データのパイプラインを渡すこと」 です。

AI に「勘で推測させる」のをやめ、「まず Cloud Trace で遅延スパンの内訳を探索させてから方針を立てさせる」 だけで、改善の精度とスピードは段違いに跳ね上がります。

「直す場所を決めずに始める。勘を捨てて事実（トレース）から入る」。人間が手を動かすときはもちろん、AI エージェントを真の意味で自律的に走らせるためにも、Observability は最大の武器になります。