debug-plan-cache-misses

Chalk のクエリプランキャッシュミスをデバッグする

Chalk は、クエリのプランニング時に、正規化された BatchQuery をキーとして、コンパイル済みのクエリプランを初回にキャッシュします。キャッシュミスが発生すると、エンジンはホットパスで再プランニングする必要があり、処理が遅くなります。クエリの形状を初めて検出したときのミスは想定内です。一方、以前のクエリと「同じに見える」クエリでミスが繰り返し発生する場合は、問題です。リクエスト内の何らかのフィールドが呼び出しごとに変化していることを意味します。

このスキルでは、（1）ログからミスを見つけ、（2）プランニングされたクエリを比較して、どのフィールドが異なり、ミスを引き起こしているのかを正確に特定します。

キャッシュキーの実際の内容

プランキャッシュキーは、正規化された BatchQuery 全体をラップします。適用される正規化は、planner_options を有効値に解決することだけです。そのため、オプションを未設定のままにする場合と、デフォルト値を明示的に設定する場合は、同じキーになり、不要なミスは発生しません。

それ以外のリクエスト内のすべての要素がキーに含まれます。次のものが該当します。

• given_features — 呼び出し元が指定する入力フィーチャーの正確なセット
• ターゲットフィーチャー（optional_target_features／required_target_features）
• tags、required_resolver_tags
• max_staleness_overrides および鮮度／再計算フラグ
• query_name_and_version
• その他の BatchQuery フィールド

したがって、これらに少しでも違いがあれば、新しいプランが作成されます。実際の環境で最もよくある原因は、given_features セットの変化です。呼び出し元が以前の呼び出しよりも多い、または少ない入力フィーチャー（たとえば、未加工の *_original 入力や、email_username のような派生入力）を指定することがあります。異なる入力セットを指定するクエリには実際に異なるプランが必要です（実行すべきリゾルバーが異なるため）。そのため、キャッシュ済みのプランは再利用できません。

ミスを示す2つのログ行

プランニングパスで、エンジンは次のログを出力します。

1. アドホックミスの警告（batch_online_query_service.py）： Ad-hoc query request with query name/version '(<name>, <version>)' missed the plan cache. The query was: <BatchQuery ...>

2. プランの計算 — アドホッククエリと名前付きクエリのどちらでも、ミスが発生するたびに出力されます。デバッグに最も役立つ行です（local_plan_factory.py）： Computed plan for [<target features>] given [<given features>] with planner options <NonNullPlannerOptions(...)>; query.query_name_and_version=(<name>, <version>)

ログ行を確認する代わりに傾向を把握したい場合は、次の statsd カウンターも利用できます。 chalk.engine.planner.python_plan_cache_miss と chalk.engine.planner.python_plan_cache_hit

chalk logs でミスを見つける

chalk logs は環境のエンジンログを検索します。まず、正しい環境／コンテキストを指定してください（chalk config、通常のプロジェクト選択、または --environment の指定）。次に、ログフィールドでクエリを実行します。

過去1日分のミス警告を検索します。

chalk logs --query 'message:"missed the plan cache"' \
  --start-time "24h ago" --end-time "now"

差分比較に最適な、特定のクエリ名のプラン計算を検索します。

chalk logs --query 'message:"Computed plan for" message:sv5_idplus_features_parallel' \
  --start-time "24h ago" --end-time "now"

ミス件数の推移を10分間隔で集計します。

chalk logs --aggregate --window-period 10m \
  --query 'message:"missed the plan cache"' --start-time "6h ago"

再現中にミスをリアルタイムで追跡します。

chalk logs --follow --query 'message:"missed the plan cache"'

クエリ構文

field:value のペアをスペースで区切ります（暗黙的な AND）。スペースまたは . を含む値は引用符で囲みます。例：message:"missed the plan cache"、query_name:"my.query"。使用できるフィールドは次のとおりです。

• message — ログメッセージに対する部分一致。上記の2つの行を検索する場合に使用します
• component — Chalk のコンポーネント。例：component:engine
• query_name — 特定の名前付きクエリで絞り込みます
• operation_id — 内部クエリ ID、correlation_id — 呼び出し元が指定したクエリ ID
• trace_id、pod_name、resource_group、deployment、app
• all_filter — 複数のフィールドを対象に一度に検索します

時間を指定するフラグ：--start-time／--end-time には、'1h ago'、'now'、または ISO-8601 形式（'2024-01-01T00:00:00Z'）を指定できます。対話型ビューアーを使う場合は、--tui を追加します。

デバッグのワークフロー

1. キャッシュミスが発生していることと、その頻度を確認します。

   chalk logs --query 'message:"missed the plan cache"' --start-time "24h ago"
   

   ここに何も表示されない場合、プランのキャッシュは機能しています。遅延の原因は別の場所にあります。

2. 対象のクエリ名について、Computed plan for の行を取得します。

   chalk logs --query 'message:"Computed plan for" message:<query_name>' \
     --start-time "24h ago"
   

3. 最新の2件の計算結果を取り出し、フィールドごとに差分を確認します。 まず given [...] のリスト（最もよくある原因）を比較し、次にターゲット特徴量のリスト、続いて planner options ブロックを比較します。異なる箇所がキャッシュミスの原因です。プランナーオプションはキーの生成前に正規化されるため、ここに差があれば、それは実際の差であり、設定値とデフォルト値の違いによるものではありません。

4. 差分の原因を呼び出し元に特定します。given セットが変動している場合、ほとんどは上流サービスが一貫性のない入力スキーマを送信していることを意味します（場合によって、生入力や派生入力が含まれたり、含まれなかったりします）。キャッシュキーを安定させ、以降の同一クエリがキャッシュにヒットするよう、呼び出し元がすべてのリクエストで安定した given_features セットを送信するよう修正します。

注意事項

• バイト単位で同一のリクエストは、2回目の呼び出しでキャッシュにヒットするはずです。そうならない場合、これはフィールドの不一致とは別の問題です（例：キャッシュが登録されていない、または共有されていない）。リクエストのせいにせず、別の問題として指摘してください。
• キャッシュミスを修正しても、すべての呼び出し元が同じリクエスト形式に収束しなければ効果はありません。異なる given セットを送信し続ける呼び出し元では、引き続きキャッシュミスが発生します。
• このスキルはログを読み取り、リクエストについて推論します。環境を変更することはありません。呼び出し元が送信する内容の変更などの修正は、ここではなく呼び出し元のコードで行います。