[CALCITE-4991] Improve RuleEventLogger to also print input rels in FULL_PLAN mode

• Type: Improvement
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 1.29.0
• Fix Version/s: 1.30.0
• Component/s: core
• Labels: pull-request-available
• Assignee: Alessandro Solimando
• Reporter: Alessandro Solimando
• Created: 21/Jan/22 10:44
• Updated: 19/Mar/22 09:17
• Resolved: 21/Jan/22 14:09

Description

After using for some time now the new plan logging capabilities introduced via RuleEventLogger in CALCITE-4704, only printing the new rel produced by a rule is not enough for complex cases, because the input rel(s) used by the rule are not printed, and sometimes they are nowhere in the logs, making it hard to understand what situation caused the appearance of a given plan of interest.

The present ticket aims at additionally printing, for FULL_PLAN marker, the input rels used by a given rule, before printing the output rel produced by the rule application.

The output logs would evolve from:

022-01-21T02:41:27,466 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Apply rule [HiveProjectFilterPullUpConstantsRule] to [rel#45:HiveProject,rel#56:HiveFilter]

2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Rule [HiveProjectFilterPullUpConstantsRule] produced [rel#58:HiveProject]
2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Full plan for [rel#58:HiveProject]:
HiveProject(month=[CAST(202110):INTEGER])
  HiveFilter(condition=[=($0, 202110)])
    HiveTableScan(table=[[default, test2]], table:alias=[test2])

to:

022-01-21T02:41:27,466 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Apply rule [HiveProjectFilterPullUpConstantsRule] to [rel#45:HiveProject,rel#56:HiveFilter]
2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Full plan for rule input [rel#45:HiveProject]:
HiveProject(month=[$0])
  HiveFilter(condition=[=($0, 202110)])
    HiveTableScan(table=[[default, test2]], table:alias=[test2])

2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Full plan for rule input [rel#56:HiveFilter]:
HiveFilter(condition=[=($0, 202110)])
  HiveTableScan(table=[[default, test2]], table:alias=[test2])

2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Rule [HiveProjectFilterPullUpConstantsRule] produced [rel#58:HiveProject]
2022-01-21T02:41:27,468 DEBUG [02c3a9eb-0565-404f-9c56-a2bbb556c827 main] calcite.RuleEventLogger: call#5: Full plan for [rel#58:HiveProject]:
HiveProject(month=[CAST(202110):INTEGER])
  HiveFilter(condition=[=($0, 202110)])
    HiveTableScan(table=[[default, test2]], table:alias=[test2])

Issue Links

• is related to: HIVE-25888 Improve RuleEventLogger to also print input rels in FULL_PLAN mode
• relates to: CALCITE-4704 Log produced plan after rule application using explain formatting
• links to: GitHub Pull Request #2697