Telemetry
When you operate a complex database system, you often need to know what is happening under the hood of the database engine, so you can optimize your queries and so on. Telemetry is a toolset that helps you to understand how your actions are planned and executed.
Query telemetry
- argument:enum(TIMINGS|PLAN)
- How much detail to profile at, TIMINGS being the default and an implicit argument — queryTelemetry() and queryTelemetry(TIMINGS) are the same constraint, and both print as the former. PLAN additionally returns the formula plan the query engine built — see below. The two are levels rather than flags: a profile carries the timings, or the timings and the plan.
The
requests the computed query telemetry for the current query. The telemetry contains detailed information about the query
processing time and its decomposition to single operations.
The query telemetry object represents a single executed operation with possibly nested other operations and consists of the following data:
- operation
- start
- When this step began, in nanoseconds. This is not a wall-clock timestamp and must never be rendered as a date.Embedded, it is a raw monotonic counter reading with no defined epoch — meaningful only relative to another reading taken in the same JVM.
- startedAt
- The wall-clock instant at which the query began. Carried by the root step only — it is what anchors the whole tree in time, so a profile can be correlated with logs, traces or another query. Every other node reports
null, and its own wall-clock position isstartedAtplus that node'sstartoffset. - steps
Internal steps of this telemetry step (operation decomposition). Same structure as the parent telemetry object.
- arguments
Arguments of the processing phase — for example, which index was selected and at what estimated cost.
- spentTime
Duration in nanoseconds, covering this step and everything nested below it.
- plan
- Structure of the formula the engine built for this phase — see below. Present only when the query asked for it, and then only on the phases that own a formula.
- metrics
- Typed numeric measurements the engine computed while answering the query. Where the durations above say where the time went, these say why — see the table below. Recorded on the root step only, so every other node reportsno metrics at all.
The metrics themselves:
| Metric | Meaning |
|---|---|
| estimatedCardinality | How many records the planner expected the filter to match |
| actualCardinality | How many records the filter really matched, before paging |
| estimatedCost | Cost the planner estimated for the formula it chose |
| actualCost | Cost that formula really incurred once it ran |
| recordsReturned | How many records were handed back, i.e. the size of the requested page |
| ioFetchCount | How many times the storage was read while assembling the response |
| ioFetchedSizeBytes | How many bytes were read from the storage |
| prefetched | Whether the planner filtered over prefetched entity bodies instead of consulting indexes — read this before interpreting a plan, see below |
The pair worth looking at first is estimatedCardinality against actualCardinality. An estimate that is off by
orders of magnitude is why the engine chose the index it chose, and it is the usual explanation for a plan that
looks wrong — no amount of timing data reveals it. estimatedCost and actualCost are the same comparison on the
planner's own unitless scale: comparable between plans of the same query, meaningless in absolute terms.
Every metric is optional, and a missing one is not a zero. A metric is recorded where the engine happens to
compute the number, so its absence means "not measured for this phase" — which is deliberately different from a
measured 0. Several of these are legitimately zero: a query answered entirely from indexes really does perform
ioFetchCount: 0 storage reads. A client that defaults absent metrics to zero will report a query that fetched
nothing as one that found nothing.
The formula plan
The timings say where the query spent itself; the plan says what it was doing. Ask for it by parametrizing the
constraint —
queryTelemetry(PLAN)
— and the steps that own a formula additionally carry the
structure of that formula:- every index-selection alternative carries the candidate the planner costed, including the ones that lost
- the root carries the plan that actually ran
That first point is the one worth the trouble. Every engine will tell you what it did; very few will tell you what it considered and rejected, and at what estimated cost. That is the information that explains a plan which looks wrong.
Each node of the plan reports:
| Property | Meaning |
|---|---|
| id | Identity of the formula instance, stable across its occurrences in the plan |
| refTo | Set only on a repeat occurrence, pointing back at the id that describes it |
| hash | Structural hash — what the cache keys on |
| description | What the formula is, in human-readable form |
| estimatedCost | What the planner expected this part to cost |
| actualCost | What it really cost, or absent if it never ran |
| resultCount | How many records it produced, or absent if it never ran |
Why refTo exists. The plan is a directed acyclic graph, not a tree: a formula's result is memoized per
instance, so a sub-formula reachable by two paths is computed once and every later occurrence of it is free.
Without the back-reference you would see the same expensive subtree twice and reasonably conclude it cost twice as
much. A node with refTo set carries no detail and no children — resolve it against the node with that id.
An absent actualCost is not a zero cost — it means the formula never ran. The planner costs every candidate
index but executes only the winner, so a rejected alternative legitimately reports no real cost at all, and so does a
branch of the winning plan that was short-circuited past.
There is a third case, and it is the one most often misread: when the planner decides it is cheaper to fetch a small
number of entity bodies and filter over those, the node described APPLY PREDICATE ON PREFETCHED ENTITIES IF POSSIBLE
answers the query from the fetched bodies and never evaluates the index branch beneath it. That whole sub-tree is
therefore reported with no actualCost and no resultCount, inside a plan that really did run. The metric that tells
you this is what happened is prefetched — check it before concluding that a large part of your plan was skipped for
some other reason.
This is deliberate and is the reason rendering the plan is safe: the renderer never computes anything. Were it to
call compute() to fill those fields in, asking for a profile would execute the plans the engine had decided to
skip — telemetry would stop observing the query and start changing it.
Note also that asking for the plan changes the profile's own numbers, because the rendering happens inside the
query being measured. A run made with the plan is not directly comparable with one made without it; re-running the
query to get the deeper view is the expected workflow.
The set of phases is not guaranteed. A query whose index selection short-circuits, or a dry run, legitimately
returns a bare root step with no children at all — clients must tolerate that rather than assume a fixed tree shape.
Note also that with telemetry enabled the absolute numbers are not production latency: instrumenting every phase
costs something, and that cost is included in what you are reading. Use the profile to find where the time goes
relative to the rest of the query, not to quote an absolute figure.
To demonstrate the information the query telemetry is providing, we will use the following query that filters and sorts entities:
The result contains query telemetry and some products (which we omitted here for brevity):