trinodb / trino

Official repository of Trino, the distributed SQL query engine for big data, formerly known as PrestoSQL (https://trino.io)
https://trino.io
Apache License 2.0
10.19k stars 2.94k forks source link

Add some debug info in LogicalPlanner#runOptimizer #23174

Open sjx782392329 opened 2 weeks ago

sjx782392329 commented 2 weeks ago

When i set io.trino=DEBUG in log.properties, I found some logical plan Optimizer can change the logical plan. But I think current debug information makes me confused. I don't know a logical plan handled by some optimizers' rules. I don’t know where the begin and end of an optimizer are. In the IterativeOptimizer rules, only can record which rules change the logical plan. Then I add some extra informations

  1. A number is added to indicate which optimizer is processing
  2. Print all the rules of IterativeOptimizer in summary
  3. When the logical execution plan is finally output, before and after are added.
  4. Added BEGIN and END to indicate the start and end of the optimizer

Then the debug informations like this

2024-08-29T15:37:37.084+0800    DEBUG   Query-20240829_073736_00002_72qqm-225   io.trino.sql.planner.LogicalPlanner     25: io.trino.sql.planner.iterative.IterativeOptimizer BEGIN
2024-08-29T15:37:37.086+0800    DEBUG   Query-20240829_073736_00002_72qqm-225   io.trino.sql.planner.iterative.IterativeOptimizer       Rule: io.trino.sql.planner.iterative.rule.PushPredicateIntoTableScan
Before:
Filter[filterPredicate = (dt = varchar '2024-08-28')]
│   Layout: [query:varchar, cluster:varchar, dt:varchar]
└─ GroupReference[groupId = 5]
       Layout: [query:varchar, cluster:varchar, dt:varchar]

After:
TableScan[table = hive:gzlc_real:fact_presto_query]
    Layout: [query:varchar, cluster:varchar, dt:varchar]
    dt := dt:string:PARTITION_KEY
        :: [[2024-08-28]]
    query := query:string:REGULAR
    cluster := cluster:string:REGULAR

2024-08-29T15:37:37.089+0800    DEBUG   Query-20240829_073736_00002_72qqm-225   io.trino.sql.planner.LogicalPlanner     25: io.trino.sql.planner.iterative.IterativeOptimizer END. Summary:
 All Rules List:
        io.trino.sql.planner.iterative.rule.ApplyTableScanRedirection
        io.trino.sql.planner.iterative.rule.PruneTableScanColumns
        io.trino.sql.planner.iterative.rule.PushPredicateIntoTableScan

Before:
Output[columnNames = [dt, query, _col2, cluster]]
│   Layout: [dt:varchar, query:varchar, count:bigint, cluster:varchar]
│   _col2 := count
└─ TopN[count = 7, orderBy = [count DESC NULLS LAST]]
   │   Layout: [dt:varchar, query:varchar, cluster:varchar, count:bigint]
   └─ Aggregate[keys = [dt, query, cluster]]
      │   Layout: [dt:varchar, query:varchar, cluster:varchar, count:bigint]
      │   count := count(*)
      └─ ScanFilter[table = hive:gzlc_real:fact_presto_query, filterPredicate = (dt = varchar '2024-08-28')]
             Layout: [query:varchar, cluster:varchar, dt:varchar]
             dt := dt:string:PARTITION_KEY
                 :: [[2023-08-31, 2024-08-29]]
             query := query:string:REGULAR
             cluster := cluster:string:REGULAR

After:
Output[columnNames = [dt, query, _col2, cluster]]
│   Layout: [dt:varchar, query:varchar, count:bigint, cluster:varchar]
│   _col2 := count
└─ TopN[count = 7, orderBy = [count DESC NULLS LAST]]
   │   Layout: [dt:varchar, query:varchar, cluster:varchar, count:bigint]
   └─ Aggregate[keys = [dt, query, cluster]]
      │   Layout: [dt:varchar, query:varchar, cluster:varchar, count:bigint]
      │   count := count(*)
      └─ TableScan[table = hive:gzlc_real:fact_presto_query]
             Layout: [query:varchar, cluster:varchar, dt:varchar]
             dt := dt:string:PARTITION_KEY
                 :: [[2024-08-28]]
             query := query:string:REGULAR
             cluster := cluster:string:REGULAR

Adding this information allows developers to see which rules are executed by each optimizer. It is convenient to check whether your rules are effective when adding new rules.

Heltman commented 2 weeks ago

I think it's a good idea. Every time I find that the execution plan is not as expected or I encounter optimizer related issues, I need to locate which rule caused this problem, but because there are so many optimization rules, it is difficult to locate which rule caused the plan change. Just like https://github.com/trinodb/trino/issues/23147, it took me a long time to determine which optimization rule caused the problem. Maybe we should make optimization rules easier to debug. @dain @raunaqmorarka @ebyhr cc