VOLCANO:Physical Planning takes long time

[Miguel Lamy <ml...@siag.pt>]

Hi , 

Planning phase in my queries is taking a lot of time. I took a look at
drill log and notice that most of the time was executing 
VOLCANO:Logical Planning (no pruning or join) and VOLCANO:Physical
Planning. 

I'm using Apache Drill 1.6.0 with jdbc storage plugins. Queries don't
take long to execute after the plan is done (I saw the profiles and
executed the physical plans). 

Can you please give me some suggestions how to debug a little further
this issue, so I can understand what's happening ? 

Thank you. 

Miguel 

Results with EXPLAIN PLAN FOR 

Example 1: 

EXPLAIN PLAN FOR SELECT e.ChvP, e.DesigEstrutura, e.CodCompiEstrutura,
e.ChvEEstrutura FROM siag_enidh.dbo.Estrutura AS e INNER JOIN
siag_enidh.dbo.Categoria AS catg ON catg.ChvP = e.ChvECategoria AND
catg.SiglaCategoria = 'CPBSQ11'; 

Line 8: 2016-05-26 07:51:34,214
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.drill.exec.store.SchemaFactory - Took 600 ms to register schemas.
    Line 15: 2016-05-26 07:51:35,563
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP:Window Function rewrites (42ms):
    Line 27: 2016-05-26 07:51:35,585
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Directory Prune Planning
(14ms):
    Line 33: 2016-05-26 07:51:36,104
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - VOLCANO:LOGICAL PLANNING (NO PRUNING
OR JOIN). (517MS):
    Line 41: 2016-05-26 07:51:36,115
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Partition Prune Planning
(10ms):
    Line 49: 2016-05-26 07:51:36,121
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:LOPT Join Planning
(5ms):
    Line 57: 2016-05-26 07:51:36,126
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Convert SUM to $SUM0
(4ms):
    Line 65: 2016-05-26 07:51:36,255
[28b8f28b-327e-6b3e-866e-df640296211a:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - VOLCANO:Physical Planning (124ms):
    Line 220: 2016-05-26 07:51:36,682
[28b8f28b-327e-6b3e-866e-df640296211a:frag:0:0] DEBUG
o.a.d.exec.physical.impl.ImplCreator - Took 150 ms to create RecordBatch
tree 

2016-05-26 07:51:36,104 [28b8f28b-327e-6b3e-866e-df640296211a:foreman]
DEBUG o.a.d.e.p.s.h.DefaultSqlHandler - VOLCANO:Logical Planning (no
pruning or join). (517ms):
DrillProjectRel(ChvP=[$0], DesigEstrutura=[$12],
CodCompiEstrutura=[$11], ChvEEstrutura=[$8]): rowcount = 100.0,
cumulative cost = {415.0 rows, 402.0 cpu, 0.0 io, 0.0 network, 0.0
memory}, id = 486
  JdbcDrel: rowcount = 100.0, cumulative cost = {415.0 rows, 402.0 cpu,
0.0 io, 0.0 network, 0.0 memory}, id = 485
    JdbcJoin(condition=[=($62, $7)], joinType=[inner]): rowcount =
100.0, cumulative cost = {315.0 rows, 302.0 cpu, 0.0 io, 0.0 network,
0.0 memory}, id = 484
      JdbcTableScan(table=[[siag_enidh, dbo, Estrutura]]): rowcount =
100.0, cumulative cost = {100.0 rows, 101.0 cpu, 0.0 io, 0.0 network,
0.0 memory}, id = 5
      JdbcFilter(condition=[=($11, 'CPBSQ11')]): rowcount = 15.0,
cumulative cost = {115.0 rows, 201.0 cpu, 0.0 io, 0.0 network, 0.0
memory}, id = 483
        JdbcTableScan(table=[[siag_enidh, dbo, Categoria]]): rowcount =
100.0, cumulative cost = {100.0 rows, 101.0 cpu, 0.0 io, 0.0 network,
0.0 memory}, id = 6 

 Example 2 taking much longer: 

Line 5: 2016-05-26 08:11:07,375
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.drill.exec.store.SchemaFactory - Took 37 ms to register schemas.
    Line 131: 2016-05-26 08:11:09,841
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP:Window Function rewrites (221ms):
    Line 381: 2016-05-26 08:11:10,171
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Directory Prune Planning
(166ms):
    Line 506: 2016-05-26 08:11:15,299
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - VOLCANO:LOGICAL PLANNING (NO PRUNING
OR JOIN). (5126MS):
    Line 641: 2016-05-26 08:11:15,386
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Partition Prune Planning
(86ms):
    Line 776: 2016-05-26 08:11:15,893
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:LOPT Join Planning
(506ms):
    Line 911: 2016-05-26 08:11:15,981
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DefaultSqlHandler - HEP_BOTTOM_UP:Convert SUM to $SUM0
(87ms):
    Line 1046: 2016-05-26 08:11:21,561
[28b8edf3-b035-6a01-4193-5295de7a16f0:foreman] DEBUG
o.a.d.e.p.s.h.DEFAULTSQLHANDLER - VOLCANO:PHYSICAL PLANNING (5579MS):
    Line 2145: 2016-05-26 08:11:21,742
[28b8edf3-b035-6a01-4193-5295de7a16f0:frag:0:0] DEBUG
o.a.d.exec.physical.impl.ImplCreator - Took 12 ms to create RecordBatch
tree