search

prestodb / presto

The official home of the Presto distributed SQL query engine for big data
http://prestodb.io
Apache License 2.0
15.97k stars 5.35k forks source link

Planning time has increased sharply since 0.144 #5188

Open zhenxiao opened 8 years ago

zhenxiao commented 8 years ago

See Presto's planning time increased a lot since 0.144, especially for tables with large number of partitions, used to have only a few seconds planning time, now comes to minutes.

electrum commented 8 years ago

Can you grab a stack trace or use a profiler to help determine where the time is being spent? If it's several minutes, even jstack should catch it.

cberner commented 8 years ago

Praveen on the mailing list tracked this down to the DesugaringOptimizer

We went through the code. Compared to version 0.131 the planning time increases in the plan optimizer phase in 0.144.1. The difference in planning time is due to DesugaringOptimizer. DesugaringOptimizer was absent in presto version 0.131.

zhenxiao commented 8 years ago

Found most of the time Coordinator is busy with this:

"Query-20160504_201841_00012_qm23i-33805" #33805 prio=5 os_prio=0 tid=0x00007fb550257800 nid=0x6144 runnable [0x00007fb3b4273000]
   java.lang.Thread.State: RUNNABLE
    at java.util.Formatter$FormatSpecifier.conversion(Formatter.java:2695)
    at java.util.Formatter$FormatSpecifier.<init>(Formatter.java:2720)
    at java.util.Formatter.parse(Formatter.java:2560)
    at java.util.Formatter.format(Formatter.java:2501)
    at java.util.Formatter.format(Formatter.java:2455)
    at java.lang.String.format(String.java:2940)
    at com.facebook.presto.spi.type.TypeSignatureParameter.getValue(TypeSignatureParameter.java:86)
    at com.facebook.presto.spi.type.TypeSignatureParameter.getNamedTypeSignature(TypeSignatureParameter.java:102)
    at com.facebook.presto.spi.type.TypeSignature$$Lambda$796/357067418.apply(Unknown Source)
    at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
    at java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1374)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
    at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
    at com.facebook.presto.spi.type.TypeSignature.rowToString(TypeSignature.java:358)
    at com.facebook.presto.spi.type.TypeSignature.toString(TypeSignature.java:323)
    at com.facebook.presto.operator.scalar.RowFieldReference.<init>(RowFieldReference.java:55)
    at com.facebook.presto.type.RowParametricType.lambda$createFunctions$1(RowParametricType.java:72)
    at com.facebook.presto.type.RowParametricType$$Lambda$802/894902213.accept(Unknown Source)
    at java.util.Optional.ifPresent(Optional.java:159)
    at com.facebook.presto.type.RowParametricType.createFunctions(RowParametricType.java:72)
    at com.facebook.presto.metadata.FunctionRegistry.getRowFieldReference(FunctionRegistry.java:575)
    at com.facebook.presto.metadata.FunctionRegistry.resolveFunction(FunctionRegistry.java:558)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitFunctionCall(ExpressionAnalyzer.java:755)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitFunctionCall(ExpressionAnalyzer.java:204)
    at com.facebook.presto.sql.tree.FunctionCall.accept(FunctionCall.java:96)
    at com.facebook.presto.sql.tree.StackableAstVisitor.process(StackableAstVisitor.java:28)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.process(ExpressionAnalyzer.java:223)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.getOperator(ExpressionAnalyzer.java:946)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitComparisonExpression(ExpressionAnalyzer.java:403)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitComparisonExpression(ExpressionAnalyzer.java:204)
    at com.facebook.presto.sql.tree.ComparisonExpression.accept(ComparisonExpression.java:133)
    at com.facebook.presto.sql.tree.StackableAstVisitor.process(StackableAstVisitor.java:28)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.process(ExpressionAnalyzer.java:223)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.coerceType(ExpressionAnalyzer.java:971)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitLogicalBinaryExpression(ExpressionAnalyzer.java:387)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitLogicalBinaryExpression(ExpressionAnalyzer.java:204)
    at com.facebook.presto.sql.tree.LogicalBinaryExpression.accept(LogicalBinaryExpression.java:85)
    at com.facebook.presto.sql.tree.StackableAstVisitor.process(StackableAstVisitor.java:28)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.process(ExpressionAnalyzer.java:223)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.coerceType(ExpressionAnalyzer.java:971)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitLogicalBinaryExpression(ExpressionAnalyzer.java:386)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.visitLogicalBinaryExpression(ExpressionAnalyzer.java:204)
    at com.facebook.presto.sql.tree.LogicalBinaryExpression.accept(LogicalBinaryExpression.java:85)
    at com.facebook.presto.sql.tree.StackableAstVisitor.process(StackableAstVisitor.java:28)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer$Visitor.process(ExpressionAnalyzer.java:223)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer.analyze(ExpressionAnalyzer.java:196)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer.analyzeExpressions(ExpressionAnalyzer.java:1125)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer.analyzeExpressionsWithSymbols(ExpressionAnalyzer.java:1095)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer.getExpressionTypes(ExpressionAnalyzer.java:1057)
    at com.facebook.presto.sql.analyzer.ExpressionAnalyzer.getExpressionTypes(ExpressionAnalyzer.java:1047)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.shouldPrune(AddExchanges.java:719)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.lambda$planTableScan$5(AddExchanges.java:645)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter$$Lambda$571/683092470.test(Unknown Source)
    at com.facebook.presto.metadata.MetadataManager$$Lambda$573/1491381358.test(Unknown Source)
    at com.facebook.presto.hive.HiveMetadata.lambda$getTableLayouts$9(HiveMetadata.java:1200)
    at com.facebook.presto.hive.HiveMetadata$$Lambda$819/1059071930.test(Unknown Source)
    at java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:174)
    at java.util.Iterator.forEachRemaining(Iterator.java:116)
    at java.util.Spliterators$IteratorSpliterator.forEachRemaining(Spliterators.java:1801)
    at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
    at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
    at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
    at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
    at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
    at com.facebook.presto.hive.HiveMetadata.getTableLayouts(HiveMetadata.java:1201)
    at com.facebook.presto.spi.connector.classloader.ClassLoaderSafeConnectorMetadata.getTableLayouts(ClassLoaderSafeConnectorMetadata.java:65)
    at com.facebook.presto.metadata.MetadataManager.getLayouts(MetadataManager.java:312)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.planTableScan(AddExchanges.java:643)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitFilter(AddExchanges.java:586)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitFilter(AddExchanges.java:191)
    at com.facebook.presto.sql.planner.plan.FilterNode.accept(FilterNode.java:71)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.planChild(AddExchanges.java:1197)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitProject(AddExchanges.java:234)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitProject(AddExchanges.java:191)
    at com.facebook.presto.sql.planner.plan.ProjectNode.accept(ProjectNode.java:81)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.planChild(AddExchanges.java:1197)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitAggregation(AddExchanges.java:286)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitAggregation(AddExchanges.java:191)
    at com.facebook.presto.sql.planner.plan.AggregationNode.accept(AggregationNode.java:189)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.planChild(AddExchanges.java:1197)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitSort(AddExchanges.java:536)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitSort(AddExchanges.java:191)
    at com.facebook.presto.sql.planner.plan.SortNode.accept(SortNode.java:87)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.planChild(AddExchanges.java:1197)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitOutput(AddExchanges.java:240)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges$Rewriter.visitOutput(AddExchanges.java:191)
    at com.facebook.presto.sql.planner.plan.OutputNode.accept(OutputNode.java:81)
    at com.facebook.presto.sql.planner.optimizations.AddExchanges.optimize(AddExchanges.java:153)
    at com.facebook.presto.sql.planner.LogicalPlanner.plan(LogicalPlanner.java:103)
    at com.facebook.presto.execution.SqlQueryExecution.doAnalyzeQuery(SqlQueryExecution.java:284)
    at com.facebook.presto.execution.SqlQueryExecution.analyzeQuery(SqlQueryExecution.java:263)
    at com.facebook.presto.execution.SqlQueryExecution.start(SqlQueryExecution.java:227)
    at com.facebook.presto.execution.QueuedExecution.lambda$start$1(QueuedExecution.java:68)
    at com.facebook.presto.execution.QueuedExecution$$Lambda$357/1906048420.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
zhenxiao commented 8 years ago

seems nothing to do with partitions, it is the invoking function call has overhead in TypeSignatureParameter

damiencarol commented 8 years ago

Same pb here with heavy memory consumption. :/

zhenxiao commented 8 years ago

@electrum @martint @cberner How do you think: https://github.com/prestodb/presto/pull/5196

I tested out in our staging cluster. The problem seems fixed with it

zhenxiao commented 8 years ago

oh, @geraint0923 did not see you get assigned. Your comments are appreciated

geraint0923 commented 8 years ago

@zhenxiao That's fine. Let's work on it.

martint commented 8 years ago

I merged @zhenxiao's change, but it might not be the only issue (especially, given what @damiencarol reported). @geraint0923 is going to continue investigating.

@damiencarol, if you have additional info (query, schema, number of partitions, etc) that you can share, please let us know.

youngwookim commented 8 years ago

I've ran into the same problem on 0.147. I did upgrade Presto from 142 to 147 after that, the problem popped up. There are high cpu usage on coordinator node and planning time for queries are increased.

geraint0923 commented 8 years ago

@youngwookim Could you please provide the example schemas and queries which have the long planning time so that we could investigate? Thanks a lot!

youngwookim commented 8 years ago

@geraint0923 I'm running Presto 0.147 with Hadoop 2.7.1 and Hive 1.2.1 The schema looks like this:

 CREATE TABLE hive.myschema.tbl1 (                                     
    c1 varchar,                                                          
    c2 timestamp,                                                               
    c3 varchar,                                                             
    c4 varchar,                                                          
    c5 varchar,                                                      
    c6 varchar,                                                            
...                                                      
    c10 array(varchar),                                                  
    c11 array(varchar),                                                 
    c12 array(varchar),                                                 
    c13 varchar,                                                               
...                                                       
    c17 varchar                                                           
 )                                                                              
 WITH (                                                                         
    format = 'ORC',                                                             
    partitioned_by = ARRAY['pc1','pc2','pc3','pc4','pc5'] 
 )

The table has 56000+ partitions and the most of my queries look like following:

SELECT pc1, pc2, c1, c2, max(...),   ...
FROM tbl
WHERE 
pc1 >= '2016-01-01' AND pc2 < '2016-01-20' AND pc3 = 'zzz' AND c4 = 'a' AND c5 > 1 
GROUP BY pc1, pc2, c1, c2 ...
ORDER BY ...

Please let me know if you need details. Thanks!

youngwookim commented 8 years ago

@geraint0923 I found an unexpected performance difference when I change the 'optimize_metadata_queries' session property. if I set 'optimize_metadata_queries' to true which is default, planning time for my query is about 25 seconds but if the property is false, then planning time is 1 second.

geraint0923 commented 8 years ago

@youngwookim Thank you for reporting. I am looking into it to see how it affects the planning.

rschlussel-zz commented 7 years ago

@geraint0923 Is there any update on this issue?

zhaiyuyong commented 6 years ago

When I upgraded from 0.123 to 0.185,I also found that planning time has grown much longer

For example:

SELECT
    log_date AS "chart_x",
        sum(total_uv)AS "aaaa",

        sum(search_uv)AS "bbbb",
        sum(order_uv)AS "cccc",
        sum(order_num)AS "dddd",
        round(sum(order_amt), 0)AS "eeee",
        CASE WHEN COALESCE(sum(order_num), 0)= 0 THEN 0 ELSE round(sum(order_amt)/ sum(order_num),2) END AS "ffff",
        round(sum(avg_index), 2)AS "gggg",

        sum(exposure_num)AS "hhhh",
        sum(click_num)AS "iiii",
        sum(list_click_uv)AS "jjjj",

        sum(list_pv)AS "kkkk",
        sum(list_click_pv)AS "llll",
        sum(search_pv)AS "mmmmm",
        sum(exposure_shop)AS "nnnnn"
FROM
    st.st_log_app_search_hotword_day_inc
WHERE
    log_date >= '2017-12-04'
    and log_date <= '2017-12-04'  and key_word in
    ('1','2','3',.....,'16351')
    and   CAST(eleme_city_id as varchar)  = '0' and entry_title = 'all' and platform = 'all'
GROUP BY
    log_date

When using version 0.123

2017-12-05T10:30:42.351+0800    INFO    query-execution-61880   com.facebook.presto.event.query.QueryMonitor    TIMELINE: Query 20171205_023034_04753_mvi6t :: elapsed 7252.00ms :: planning 1.54s :: scheduling 763.00ms :: running 4940.00ms :: finishing 6.00ms :: begin 2017-12-05T10:30:35.055+08:00 :: end 2017-12-05T10:30:42.307+08:00

When using version 0.185

2017-12-05T10:23:22.600+0800    INFO    query-execution-1112    com.facebook.presto.event.query.QueryMonitor    TIMELINE: Query 20171205_022238_07939_8kvz9=FINISHED:: Transaction:[30a07de8-cce6-45d3-b4aa-896d3de35a6a] :: elapsed 43686ms :: queued 0ms :: planning 28476ms :: scheduling 5812ms :: running 9394ms :: finishing 4ms :: begin 2017-12-05T10:22:38.654+08:00 :: end 2017-12-05T10:23:22.340+08:00

When using version 0.189

2017-12-05T11:09:19.433+0800    INFO    query-execution-5   com.facebook.presto.event.query.QueryMonitor    TIMELINE: Query 20171205_030830_00008_53erk :: Transaction:[009b8e0d-effe-40eb-a0e4-5dbbbff7436b] :: elapsed 47370ms :: planning 30225ms :: scheduling 3237ms :: running 13925ms :: finishing 0ms :: begin 2017-12-05T11:08:30.547+08:00 :: end 2017-12-05T11:09:17.917+08:00