Chun Chang created DRILL-4311:
---------------------------------
Summary: Unexpected exception during fragment initialization:
Internal error: Error while applying rule DrillTableRule, args
[rel#6431439:EnumerableTableScan.ENUMERABLE.ANY([]).[](table=[hive,
lineitem_text_partitioned_hive_hier_intstring])]
Key: DRILL-4311
URL: https://issues.apache.org/jira/browse/DRILL-4311
Project: Apache Drill
Issue Type: Bug
Components: Execution - Flow
Affects Versions: 1.5.0
Reporter: Chun Chang
1.5.0-SNAPSHOT 3d0b4b02521f12e3871d6060c8f9bfce73b218a0
Hit the following exception while running Functional automation. It's not
specific to a query. The same query passed in other runs. So looks random. And
feels the current master is less stable than a few days ago.
{noformat}
2016-01-26 05:22:05,991 [29588d02-6fc1-3e49-4e4b-de4cc6205538:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
29588d02-6fc1-3e49-4e4b-de4cc6205538: select l_orderkey, l_partkey, l_quantity,
l_shipdate, l_shipinstruct from
hive.lineitem_text_partitioned_hive_hier_intstring where `year`=1993 and
l_orderkey > 29600 and `month`='nov'
2016-01-26 05:22:05,990 [29588d02-7206-dac7-a1dd-bb4a99fed1b9:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 85 out of
85 using 16 threads. Time: 13ms total, 2.287035ms avg, 3ms max.
2016-01-26 05:22:05,982 [29588d01-bfc1-49db-caa3-baabb0b9ff30:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
29588d01-bfc1-49db-caa3-baabb0b9ff30: select distinct count(distinct c_row)
from data group by c_int order by 1
2016-01-26 05:22:05,995 [29588d02-7206-dac7-a1dd-bb4a99fed1b9:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 85 out of
85 using 16 threads. Earliest start: 400.204000 μs, Latest start: 12264.460000
μs, Average start: 5804.976765 μs .
2016-01-26 05:22:05,995 [29588d02-0b3c-0b0f-fbac-c219dd631d92:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d02-0b3c-0b0f-fbac-c219dd631d92:0:0:
State to report: RUNNING
2016-01-26 05:22:05,997 [29588d02-0b3c-0b0f-fbac-c219dd631d92:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d02-0b3c-0b0f-fbac-c219dd631d92:0:0:
State change requested RUNNING --> FINISHED
2016-01-26 05:22:05,997 [29588d02-0b3c-0b0f-fbac-c219dd631d92:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d02-0b3c-0b0f-fbac-c219dd631d92:0:0:
State to report: FINISHED
2016-01-26 05:22:05,997 [29588d02-7206-dac7-a1dd-bb4a99fed1b9:foreman] INFO
o.a.d.e.p.l.partition.PruneScanRule - Total pruning elapsed time: 128 ms
2016-01-26 05:22:06,016 [29588d01-51bd-c95b-a4ef-692ababd0a05:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
29588d01-51bd-c95b-a4ef-692ababd0a05: use `dfs`
2016-01-26 05:22:06,137 [29588d01-c725-8642-b99d-e902fd4e7f93:foreman] INFO
o.a.d.e.s.schedule.BlockMapBuilder - Get block maps: Executed 1 out of 1 using
1 threads. Time: 0ms total, 0.945990ms avg, 0ms max.
2016-01-26 05:22:06,137 [29588d01-c725-8642-b99d-e902fd4e7f93:foreman] INFO
o.a.d.e.s.schedule.BlockMapBuilder - Get block maps: Executed 1 out of 1 using
1 threads. Earliest start: 0.219000 μs, Latest start: 0.219000 μs, Average
start: 0.219000 μs .
2016-01-26 05:22:06,138 [29588d01-bfc1-49db-caa3-baabb0b9ff30:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Took 0 ms to get file statuses
2016-01-26 05:22:06,139 [29588d01-bfc1-49db-caa3-baabb0b9ff30:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1
using 1 threads. Time: 1ms total, 1.486007ms avg, 1ms max.
2016-01-26 05:22:06,140 [29588d01-bfc1-49db-caa3-baabb0b9ff30:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Fetch parquet metadata: Executed 1 out of 1
using 1 threads. Earliest start: 0.390000 μs, Latest start: 0.390000 μs,
Average start: 0.390000 μs .
2016-01-26 05:22:06,140 [29588d01-bfc1-49db-caa3-baabb0b9ff30:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Took 1 ms to read file metadata
2016-01-26 05:22:06,169 [29588d01-c725-8642-b99d-e902fd4e7f93:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d01-c725-8642-b99d-e902fd4e7f93:0:0:
State change requested AWAITING_ALLOCATION --> RUNNING
2016-01-26 05:22:06,169 [29588d01-c725-8642-b99d-e902fd4e7f93:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d01-c725-8642-b99d-e902fd4e7f93:0:0:
State to report: RUNNING
2016-01-26 05:22:06,175 [29588d02-7206-dac7-a1dd-bb4a99fed1b9:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d02-7206-dac7-a1dd-bb4a99fed1b9:0:0:
State change requested AWAITING_ALLOCATION --> RUNNING
2016-01-26 05:22:06,175 [29588d02-7206-dac7-a1dd-bb4a99fed1b9:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d02-7206-dac7-a1dd-bb4a99fed1b9:0:0:
State to report: RUNNING
2016-01-26 05:22:06,247 [29588d01-c725-8642-b99d-e902fd4e7f93:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d01-c725-8642-b99d-e902fd4e7f93:0:0:
State change requested RUNNING --> FINISHED
2016-01-26 05:22:06,248 [29588d01-c725-8642-b99d-e902fd4e7f93:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d01-c725-8642-b99d-e902fd4e7f93:0:0:
State to report: FINISHED
2016-01-26 05:22:06,248 [29588d01-51bd-c95b-a4ef-692ababd0a05:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d01-51bd-c95b-a4ef-692ababd0a05:0:0:
State change requested AWAITING_ALLOCATION --> RUNNING
2016-01-26 05:22:06,248 [29588d01-51bd-c95b-a4ef-692ababd0a05:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d01-51bd-c95b-a4ef-692ababd0a05:0:0:
State to report: RUNNING
2016-01-26 05:22:06,249 [29588d01-51bd-c95b-a4ef-692ababd0a05:frag:0:0] INFO
o.a.d.e.w.fragment.FragmentExecutor - 29588d01-51bd-c95b-a4ef-692ababd0a05:0:0:
State change requested RUNNING --> FINISHED
2016-01-26 05:22:06,249 [29588d01-51bd-c95b-a4ef-692ababd0a05:frag:0:0] INFO
o.a.d.e.w.f.FragmentStatusReporter - 29588d01-51bd-c95b-a4ef-692ababd0a05:0:0:
State to report: FINISHED
2016-01-26 05:22:06,292 [29588d02-6fc1-3e49-4e4b-de4cc6205538:foreman] ERROR
o.a.drill.exec.work.foreman.Foreman - SYSTEM ERROR: NullPointerException
[Error Id: ac0f28f9-b569-4eac-af54-bedbce33278a on atsqa6c61.qa.lab:31010]
org.apache.drill.common.exceptions.UserException: SYSTEM ERROR:
NullPointerException
[Error Id: ac0f28f9-b569-4eac-af54-bedbce33278a on atsqa6c61.qa.lab:31010]
at
org.apache.drill.common.exceptions.UserException$Builder.build(UserException.java:543)
~[drill-common-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.work.foreman.Foreman$ForemanResult.close(Foreman.java:746)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.work.foreman.Foreman$StateSwitch.processEvent(Foreman.java:858)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.work.foreman.Foreman$StateSwitch.processEvent(Foreman.java:790)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.common.EventProcessor.sendEvent(EventProcessor.java:73)
[drill-common-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.work.foreman.Foreman$StateSwitch.moveToState(Foreman.java:792)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.work.foreman.Foreman.moveToState(Foreman.java:909)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at org.apache.drill.exec.work.foreman.Foreman.run(Foreman.java:261)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[na:1.7.0_45]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[na:1.7.0_45]
at java.lang.Thread.run(Thread.java:744) [na:1.7.0_45]
Caused by: org.apache.drill.exec.work.foreman.ForemanException: Unexpected
exception during fragment initialization: Internal error: Error while applying
rule DrillTableRule, args
[rel#6431439:EnumerableTableScan.ENUMERABLE.ANY([]).[](table=[hive,
lineitem_text_partitioned_hive_hier_intstring])]
... 4 common frames omitted
Caused by: java.lang.AssertionError: Internal error: Error while applying rule
DrillTableRule, args
[rel#6431439:EnumerableTableScan.ENUMERABLE.ANY([]).[](table=[hive,
lineitem_text_partitioned_hive_hier_intstring])]
at org.apache.calcite.util.Util.newInternal(Util.java:792)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoRuleCall.onMatch(VolcanoRuleCall.java:251)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:808)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.tools.Programs$RuleSetProgram.run(Programs.java:303)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.prepare.PlannerImpl.transform(PlannerImpl.java:313)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.drill.exec.planner.sql.handlers.DefaultSqlHandler.doLogicalPlanning(DefaultSqlHandler.java:542)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.planner.sql.handlers.DefaultSqlHandler.convertToDrel(DefaultSqlHandler.java:218)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.planner.sql.handlers.DefaultSqlHandler.convertToDrel(DefaultSqlHandler.java:252)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.planner.sql.handlers.DefaultSqlHandler.getPlan(DefaultSqlHandler.java:172)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.planner.sql.DrillSqlWorker.getPlan(DrillSqlWorker.java:199)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at org.apache.drill.exec.work.foreman.Foreman.runSQL(Foreman.java:924)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at org.apache.drill.exec.work.foreman.Foreman.run(Foreman.java:250)
[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
... 3 common frames omitted
Caused by: java.lang.AssertionError: Internal error: Error occurred while
applying rule DrillTableRule
at org.apache.calcite.util.Util.newInternal(Util.java:792)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoRuleCall.transformTo(VolcanoRuleCall.java:150)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.RelOptRuleCall.transformTo(RelOptRuleCall.java:213)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.drill.exec.planner.logical.DrillScanRule.onMatch(DrillScanRule.java:37)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.calcite.plan.volcano.VolcanoRuleCall.onMatch(VolcanoRuleCall.java:228)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
... 13 common frames omitted
Caused by: java.lang.reflect.UndeclaredThrowableException: null
at com.sun.proxy.$Proxy69.getNonCumulativeCost(Unknown Source) ~[na:na]
at
org.apache.calcite.rel.metadata.RelMetadataQuery.getNonCumulativeCost(RelMetadataQuery.java:115)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.getCost(VolcanoPlanner.java:1112)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.RelSubset.propagateCostImprovements0(RelSubset.java:363)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.RelSubset.propagateCostImprovements(RelSubset.java:344)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.addRelToSet(VolcanoPlanner.java:1827)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.registerImpl(VolcanoPlanner.java:1760)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.register(VolcanoPlanner.java:1017)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1037)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoPlanner.ensureRegistered(VolcanoPlanner.java:1940)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
at
org.apache.calcite.plan.volcano.VolcanoRuleCall.transformTo(VolcanoRuleCall.java:138)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
... 16 common frames omitted
Caused by: java.lang.reflect.InvocationTargetException: null
at sun.reflect.GeneratedMethodAccessor34.invoke(Unknown Source) ~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.7.0_45]
at java.lang.reflect.Method.invoke(Method.java:606) ~[na:1.7.0_45]
at
org.apache.calcite.rel.metadata.ReflectiveRelMetadataProvider$1$1.invoke(ReflectiveRelMetadataProvider.java:182)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
... 27 common frames omitted
Caused by: org.apache.drill.common.exceptions.DrillRuntimeException:
java.io.IOException: Failed to get numRows from HiveTable
at
org.apache.drill.exec.store.hive.HiveScan.getScanStats(HiveScan.java:233)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.physical.base.AbstractGroupScan.getScanStats(AbstractGroupScan.java:76)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.planner.logical.DrillScanRel.computeSelfCost(DrillScanRel.java:164)
~[drill-java-exec-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.calcite.rel.metadata.RelMdPercentageOriginalRows.getNonCumulativeCost(RelMdPercentageOriginalRows.java:165)
~[calcite-core-1.4.0-drill-r10.jar:1.4.0-drill-r10]
... 31 common frames omitted
Caused by: java.io.IOException: Failed to get numRows from HiveTable
at
org.apache.drill.exec.store.hive.HiveMetadataProvider.getStats(HiveMetadataProvider.java:113)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.store.hive.HiveScan.getScanStats(HiveScan.java:224)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
... 34 common frames omitted
Caused by: java.lang.NullPointerException: null
at com.mapr.fs.MapRFileSystem.globStatus(MapRFileSystem.java:1241)
~[maprfs-4.1.0-mapr.jar:4.1.0-mapr]
at
org.apache.hadoop.mapred.FileInputFormat.singleThreadedListStatus(FileInputFormat.java:259)
~[hadoop-mapreduce-client-core-2.7.0-mapr-1506.jar:na]
at
org.apache.hadoop.mapred.FileInputFormat.listStatus(FileInputFormat.java:229)
~[hadoop-mapreduce-client-core-2.7.0-mapr-1506.jar:na]
at
org.apache.hadoop.mapred.FileInputFormat.getSplits(FileInputFormat.java:317)
~[hadoop-mapreduce-client-core-2.7.0-mapr-1506.jar:na]
at
org.apache.drill.exec.store.hive.HiveMetadataProvider$1.run(HiveMetadataProvider.java:253)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.store.hive.HiveMetadataProvider$1.run(HiveMetadataProvider.java:241)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at java.security.AccessController.doPrivileged(Native Method)
~[na:1.7.0_45]
at javax.security.auth.Subject.doAs(Subject.java:415) ~[na:1.7.0_45]
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1595)
~[hadoop-common-2.7.0-mapr-1506.jar:na]
at
org.apache.drill.exec.store.hive.HiveMetadataProvider.splitInputWithUGI(HiveMetadataProvider.java:241)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.store.hive.HiveMetadataProvider.getPartitionInputSplits(HiveMetadataProvider.java:142)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
at
org.apache.drill.exec.store.hive.HiveMetadataProvider.getStats(HiveMetadataProvider.java:105)
~[drill-storage-hive-core-1.5.0-SNAPSHOT.jar:1.5.0-SNAPSHOT]
... 35 common frames omitted
{noformat}
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
