Optimizer exhausted the time limit

See original GitHub issue

In Presto 0.188 with iterative optimizer, we are observing “The optimizer exhausted the time limit” error for certain types of queries, which usually contain many operations (more than 2000 nodes) and table references.

We’ve also tried to increase experimental.iterative-optimizer-timeout from 3m to 10m, but it was not sufficient. Here is a copy of the stack trace:

Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: com.facebook.presto.spi.PrestoException: The optimizer exhausted the time limit of 180000 ms
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreNode(IterativeOptimizer.java:118)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:93)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreChildren(IterativeOptimizer.java:182)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.exploreGroup(IterativeOptimizer.java:95)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.iterative.IterativeOptimizer.optimize(IterativeOptimizer.java:84)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.LogicalPlanner.plan(LogicalPlanner.java:133)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.sql.planner.LogicalPlanner.plan(LogicalPlanner.java:122)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.execution.SqlQueryExecution.doAnalyzeQuery(SqlQueryExecution.java:366)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.execution.SqlQueryExecution.analyzeQuery(SqlQueryExecution.java:345)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.facebook.presto.execution.SqlQueryExecution.start(SqlQueryExecution.java:277)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at com.treasure_data.presto.server.TDQueryExecution.start(TDQueryExecution.java:118)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
Nov 17 01:38:56 ip-172-18-132-23 presto[37566]: #011at java.lang.Thread.run(Thread.java:745)

We cannot expose this specific query (because this is our customer’s query), but we are now trying to create an example that causes this long optimization time. By disabling iterative-optimizer, the query runs normally.

Issue Analytics

State:
Created 6 years ago
Comments:18 (18 by maintainers)

Top GitHub Comments

4reactions

miniwaycommented, Jan 10, 2018

I confirmed that @kokosing #9705 has solved the issue!

2reactions

kokosingcommented, Nov 17, 2017

Can you please attach the profiller? The most likely IterativeOptimizer stuck in a cycle, so profiller log should point out which rules participate in cycle.

Just for test reason, can you please increase experimental.iterative-optimizer-timeout to something like an hour, to see if IterativeOptimizer ends eventually. That would mean there is no cycle, but there is something to optimize in optimizer.

Top Results From Across the Web

Understanding Optimizer Timeout and how Complex queries ...

The Query Optimizer may dynamically adjust/set timeout threshold based on the cost of the plan found at a certain stage. For example, if...

How can I increase the maximum query time? - Stack Overflow

When executing queries, Presto restricts each query by CPU, memory, execution time and other constraints. You hit execution time limit.

Release 0.168 — Presto 0.278 Documentation

Add a time limit for the iterative optimizer. It can be adjusted via the iterative_optimizer_timeout session property or experimental.iterative-optimizer- ...

Optimizer properties — Trino 403 Documentation

This allows Trino to execute some simple queries in constant time. Currently, this optimization applies to max , min and approx_distinct of partition...

Solving query optimization in Presto - InfoWorld

The goals include minimizing the data read from disk (predicate and limit pushdown, column pruning, etc.) and reducing network transfer of data ...