Skip to content

Log before/after plans when an optimizer rule fires - #19117

Open
ColinLeeo wants to merge 1 commit into
apache:masterfrom
ColinLeeo:fix/optimizer-rule-debug-log-plans
Open

ColinLeeo wants to merge 1 commit into
apache:masterfrom
ColinLeeo:fix/optimizer-rule-debug-log-plans

Conversation

@ColinLeeo

Copy link
Copy Markdown
Collaborator

Motivation

IterativeOptimizer logs every rule application at DEBUG level, but the before/after plan slots were filled with empty strings:

LOG.debug(DataNodeQueryMessages.RULE_S_BEFORE_S_AFTER_S, rule.getClass().getName(), "", "");

The message template is "Rule: {}\nBefore:\n{}\nAfter:\n{}", so enabling DEBUG for this logger produced a rule name followed by two blank sections — the log existed but carried no diagnostic value. This is a leftover from the initial table-model port; the placeholders were never filled in (verified via git log: they were already empty before the i18n conversion of this literal).

Changes

  • IterativeOptimizer: render the node being rewritten and the transformed plan with the existing PlanGraphJsonPrinter, and pass them into the log.
  • PlanGraphJsonPrinter: treat GroupReference as a leaf. Optimizer-internal nodes have GroupReference children, and GroupReference.getChildren() throws UnsupportedOperationException, which made both plan printers fail on such plans. This is a no-op for EXPLAIN, where group references never appear.
  • Rule timing is now taken before logging, so enabling DEBUG no longer inflates the recorded rule execution time.

Rendering is best-effort and debug-gated: if rendering throws, the log falls back to the node's toString, so a debug log can never fail a query.

Example output

With DEBUG enabled for org.apache.iotdb.db.queryengine.plan.relational.planner.iterative.IterativeOptimizer:

Rule: ...rule.InlineProjections
Before:
{
  "name": "ProjectNode-8",
  "id": "8",
  "properties": {
    "OutputSymbols": ["device_id$gid", "count"],
    "Expressions": ["\"device_id$gid\"", "\"count\""]
  },
  "children": [{ "name": "GroupReference-19", "id": "19" }]
}
After:
{
  "name": "ProjectNode-8",
  ...
  "children": [{ "name": "GroupReference-20", "id": "20" }]
}

Test plan

  • PlanGraphJsonPrinterTest — added testGroupReferenceIsRenderedAsLeaf, which renders a plan whose child is a GroupReference and asserts it is emitted as a leaf and that rendering does not throw.
  • Ran PlanGraphJsonPrinterTest, PlanGraphPrinterTest and TableModelPlannerTest: 21 tests, 0 failures.
  • End-to-end: built the distribution, enabled the DEBUG logger, ran a table-model query with a subquery; all 13 rule applications rendered real plans, with no fallback and no exception in the server log.

🤖 Generated with Claude Code

The rule-application debug log in IterativeOptimizer passed empty strings for
the before/after plan slots, so enabling DEBUG produced entries with a rule
name and two blank sections.

Render the node being rewritten and the transformed plan instead, using the
existing PlanGraphJsonPrinter. To make that work for optimizer-internal plans,
treat GroupReference as a leaf in the printer: it throws from getChildren(),
which previously made the whole render fail.

Rendering is best-effort and debug-gated; a rendering failure falls back to the
node's toString so a debug log can never fail a query. Rule timing is now taken
before logging, so enabling DEBUG no longer inflates the recorded rule time.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant