Debug Chalk query plan cache misses
Chalk caches a compiled query plan the first time it plans a query, keyed by a
normalized
. A
cache miss forces the engine to replan on the
hot path, which is slow. Misses are expected the first time a query shape is
seen; they are a
problem when a query that "looks identical" to a previous
one keeps missing — that means some field in the request is varying between
calls.
This skill: (1) finds misses in the logs, and (2) diffs the planned queries to
identify exactly which field differs and forces the miss.
What the cache key actually is
The plan cache key wraps the
entire normalized . The only
normalization applied is that
are resolved to their
effective values — so leaving an option unset and setting it explicitly to its
default produce the
same key and will not cause a spurious miss.
Everything else in the request is part of the key, including:
- — the exact set of input features the caller provides
- target features ( / )
- ,
- and staleness/recompute flags
- and the remaining fields
So
any difference in these forces a new plan. The single most common
real-world cause is a
varying set — the caller sometimes
supplies more or fewer input features (e.g. raw
inputs, or derived
inputs like
) than a previous call. A query that provides a
different set of inputs genuinely needs a different plan (different resolvers
must run), so it cannot reuse the cached one.
The two log lines that signal a miss
The engine emits these on the planning path:
-
Ad-hoc miss warning (
batch_online_query_service.py
):
Ad-hoc query request with query name/version '(<name>, <version>)' missed the plan cache. The query was: <BatchQuery ...>
-
Plan computation — emitted on
every miss (ad-hoc or named), and the
most useful line for debugging (
):
Computed plan for [<target features>] given [<given features>] with planner options <NonNullPlannerOptions(...)>; query.query_name_and_version=(<name>, <version>)
There are also statsd counters if you want to trend rather than read lines:
chalk.engine.planner.python_plan_cache_miss
vs
chalk.engine.planner.python_plan_cache_hit
.
Finding misses with
searches the environment's engine logs. Point it at the right
environment/context first (
/ the usual project or
selection), then query by log fields.
Search for the miss warnings over the last day:
sh
chalk logs --query 'message:"missed the plan cache"' \
--start-time "24h ago" --end-time "now"
Search for plan computations for one query name (best for diffing):
sh
chalk logs --query 'message:"Computed plan for" message:sv5_idplus_features_parallel' \
--start-time "24h ago" --end-time "now"
Trend miss volume over time in 10-minute buckets:
sh
chalk logs --aggregate --window-period 10m \
--query 'message:"missed the plan cache"' --start-time "6h ago"
Tail misses live while reproducing:
sh
chalk logs --follow --query 'message:"missed the plan cache"'
Query syntax
pairs, space-separated (implicit AND). Quote any value that
contains a space or a
— e.g.
message:"missed the plan cache"
,
. Useful fields:
- — substring match on the log message (use this for the two lines above)
- — Chalk component, e.g.
- — filter to a specific named query
- — internal query id; — caller-supplied query id
- , , , ,
- — match across multiple fields at once
Time flags:
/
accept
,
, or
ISO-8601 (
). Add
for an interactive viewer.
Debugging workflow
-
Confirm misses are happening and how often:
sh
chalk logs --query 'message:"missed the plan cache"' --start-time "24h ago"
If this is empty, plan caching is working — look elsewhere for the latency.
-
Pull the
lines for the affected query name:
sh
chalk logs --query 'message:"Computed plan for" message:<query_name>' \
--start-time "24h ago"
-
Take the two most recent computations and
diff them field by field:
compare the
lists first (most common culprit), then the
target-feature lists, then the
block. Whatever differs is
the cause of the miss. Because planner options are normalized before keying,
a difference there is a real difference — not a set-vs-default artifact.
-
Attribute the difference to the caller. A varying
set almost always
means an upstream service is sending an inconsistent input schema (sometimes
including raw/derived inputs, sometimes not). The fix is to make the caller
send a
stable set on every request so the key is
stable and subsequent identical queries hit the cache.
Notes
- Two byte-identical requests should hit the cache on the second call. If they
don't, that's a distinct issue from a field mismatch (e.g. cache not being
populated/shared) — call it out separately rather than blaming the request.
- Fixing a miss only helps if all callers converge on one request shape. If
some callers still send a different set, those keep missing.
- This skill reads logs and reasons about the request; it does not mutate any
environment. Any remediation (changing what a caller sends) happens in the
caller's code, not here.