Skip to content

Include stats for each planner phase in EXPLAIN metrics #3512

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 9 commits into
base: main
Choose a base branch
from

Conversation

hazefully
Copy link

@hazefully hazefully commented Jul 29, 2025

This PR adds new stats to the PLANNER_METRICS struct produced for EXPLAIN SQL queries which reflect the number of tasks in each planner phase and the total time the tasks for each phase took to execute. It also adds a new lightweight Cascades debugger implementation which only keeps tracks of debugger events.

To achieve this, the PR includes the following changes:

  • 2582ff8: This commit splits the cascades.debug.Debugger interface into two
    separate interfaces (StatsDebugger and SymbolDebugger) which both extend the base Debugger interface, in
    order to ensure that operations related to recording Debugger events (with the purpose of calculating stats
    based on the profiling of these events) make use of the StatsDebugger interface, and similarly operations related to
    registering different objects used within the planner make use of the SymbolDebugger interface. The State class which kept track of symbols and debugger events is also split into two different classes: EventState and SymbolTables.

  • bdf2e16: This commit extracts the functionality of rendering the different stats for debugger events from the State class to a separate StatsViewer class.

  • cf9848b and a9edd0f: These two commits include the main work of grouping debugger events by the planner phase they were emitted in, and exposing that grouping in the EXPLAIN planner metrics. As a result of this grouping the "Event Profiling" rendered by the StatsViewer class is now split by phase as well:

    image

    In addition, the result set of an EXPLAIN query contains the expected planner metrics:

      { TASK_COUNT -> 248
      , TASK_TOTAL_TIME_NS -> 98967370
      , TRANSFORM_COUNT -> 61
      , TRANSFORM_TIME_NS -> 77887334
      , TRANSFORM_YIELD_COUNT -> 29
      , INSERT_TIME_NS -> 2012374
      , INSERT_NEW_COUNT -> 22
      , INSERT_REUSED_COUNT -> 6
      , REWRITING_PHASE_TASK_COUNT -> 44
      , PLANNING_PHASE_TASK_COUNT -> 204
      , REWRITING_PHASE_TASKS_TOTAL_TIME_NS -> 7869126
      , PLANNING_PHASE_TASKS_TOTAL_TIME_NS -> 91098244
      } 
    
  • 2ee4763: This commit adds the new lightweight debugger implementation that only implements the StatsDebugger interface.


Note: This PR previously took a different approach to expose the duration each planner phase took (12b5817), but after offline discussions we decided to make use of the existing Cascades debugger to expose these metrics.

@hazefully hazefully added the enhancement New feature or request label Jul 29, 2025
@hazefully hazefully force-pushed the planner-phase-metrics branch 2 times, most recently from b71ab35 to 7e8cc8e Compare July 29, 2025 18:12
@hazefully hazefully force-pushed the planner-phase-metrics branch 2 times, most recently from 8814a6c to da8ae22 Compare August 8, 2025 14:45
@hazefully hazefully changed the title Introduce new timers for the different phases of the Cascades planner Include stats for each planner phase in EXPLAIN metrics Aug 8, 2025
@hazefully hazefully force-pushed the planner-phase-metrics branch from da8ae22 to 668c47e Compare August 8, 2025 15:16
@hazefully hazefully changed the title Include stats for each planner phase in EXPLAIN metrics Include stats for each planner phase in EXPLAIN planner metrics Aug 8, 2025
@hazefully hazefully changed the title Include stats for each planner phase in EXPLAIN planner metrics Include stats for each planner phase in EXPLAIN metrics Aug 8, 2025
This commit introduces new StoreTimer.Events that record how long each phase (rewriting, planning)
of the Cascades planner take. To achieve this, the Relational layer passes the instance of StoreTimer
within the current transaction to the Cascades planner upon creation, which it makes use of by recording
the time a phase took using a new Cascades task, `FinalizePlannerPhase`, which simply calls record on the
StoreTimer instance (if it is not `null`) with the total time the planner phase took. The
`FinalizePlannerPhase` task is schedueled to be executed by the `InitiatePlannerPhase` task, ensuring that
it is the last task that is run for that phase.

In addition, the logs for queries (which happen if debug logging is enabled or if a query is too slow) is enhanced
to include the durations for the two planner phases.
This commit splits the com.apple.foundationdb.record.query.plan.cascades.debug.Debugger interface into two
separate interfaces (StatsDebugger and SymbolDebugger) which both extend the base Debugger interface, in
order to ensure that operations related to recording Debugger events (with the purpose of calculating stats
based on the profiling of these events) make use of the StatsDebugger interface, and operations related to
keeping a registry of all Symbols used within the planner for purposes of associating them with friendly names
make use of the SymbolDebugger interface.

In addition to splitting the Debugger interface, the State class is also split into two classes, one that keeps
of the Debugger events and stats around them (EventState) and one that keeps track of the current Symbols seen
during planning (SymbolTables).
This commit modifies the EventState class and the StatsMaps that it produces
to group Debugger events by the planner phase it was emitted during to enable
the ability of getting stats for each planner phase separately.

Given that some Debugger events (e.g. InsertIntoMemoEvent) do not store the
planner phase they were emitted in (as it not visible to the code that emits
them), these events are stored separately and can be retrieved from the
StatsMaps (in addition to the ability of retrieving all events, regardless
of the planner phase that they were emitted in).
This commit adds a new implmentation of the Cascades Debugger interface,
which only keeps track of statstics around debugger events and doesn't support
keeping track of symbol tables. This new implementation should be safe to
use outside of tests since it should have a minimal impact on the planner's
performance.
@hazefully hazefully force-pushed the planner-phase-metrics branch from 668c47e to 2ee4763 Compare August 8, 2025 15:37
@hazefully hazefully marked this pull request as ready for review August 8, 2025 16:51
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
enhancement New feature or request
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant