zhangdove commented on issue #1831:
URL: https://github.com/apache/iceberg/issues/1831#issuecomment-734670458
```
2020-11-27T14:10:51,474 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 137
2020-11-27T14:10:51,476 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,477 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] operation.OperationManager: Adding
operation: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]
2020-11-27T14:10:51,478 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Driver: Acquired the compile lock.
2020-11-27T14:10:51,478 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=Driver.run
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,478 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=compile
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,478 DEBUG [HiveServer2-Handler-Pool: Thread-32]
conf.VariableSubstitution: Substitution is on: select * from db.tb
2020-11-27T14:10:51,478 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Driver: Compiling
command(queryId=dovezhang_20201127141051_08c245d8-c816-41fb-8d0a-4f06d6e2b50d):
select * from db.tb
2020-11-27T14:10:51,479 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=parse
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,479 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.ParseDriver: Parsing command: select
* from db.tb
2020-11-27T14:10:51,479 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.ParseDriver: Parse Completed
2020-11-27T14:10:51,479 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=parse
start=1606457451479 end=1606457451479 duration=0
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,479 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG
method=semanticAnalyze from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,481 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Starting Semantic
Analysis
2020-11-27T14:10:51,481 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Completed phase 1 of
Semantic Analysis
2020-11-27T14:10:51,481 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
source tables
2020-11-27T14:10:51,528 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
subqueries
2020-11-27T14:10:51,528 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
destination tables
2020-11-27T14:10:51,529 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.Client: The ping interval is 60000 ms.
2020-11-27T14:10:51,529 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.Client: Connecting to localhost/127.0.0.1:8020
2020-11-27T14:10:51,532 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive: starting, having connections 1
2020-11-27T14:10:51,532 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#193
2020-11-27T14:10:51,548 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #193
2020-11-27T14:10:51,549 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getEZForPath took 21ms
2020-11-27T14:10:51,549 DEBUG [HiveServer2-Handler-Pool: Thread-32]
hdfs.DFSClient:
/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1:
masked=rwx------
2020-11-27T14:10:51,549 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#194
2020-11-27T14:10:51,551 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #194
2020-11-27T14:10:51,551 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: mkdirs took 2ms
2020-11-27T14:10:51,551 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#195
2020-11-27T14:10:51,552 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #195
2020-11-27T14:10:51,552 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,552 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: New scratch dir is
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1
2020-11-27T14:10:51,553 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Completed getting
MetaData in Semantic Analysis
2020-11-27T14:10:51,554 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,554 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] hive.log: DDL: struct tb { i32 id,
timestamp ts}
2020-11-27T14:10:51,554 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] lazy.LazySerDeParameters:
org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe initialized with:
columnNames=[id, ts] columnTypes=[int, timestamp] separator=[[B@10ff9ec1]
nullstring=\N lastColumnTakesRest=false timestampFormats=null
2020-11-27T14:10:51,555 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Plan for
Query Block null
2020-11-27T14:10:51,555 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451554 end=1606457451555 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Plan generation>
2020-11-27T14:10:51,556 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] calcite.sql2rel: Plan after trimming
unused fields
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,564 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Plan before removing
subquery:
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,564 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#296:HiveProject.HIVE.[](input=HepRelVertex#295,id=$0,ts=$1)
2020-11-27T14:10:51,564 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Plan just after
removing subquery:
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Plan after
decorrelation:
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#299:HiveProject.HIVE.[](input=HepRelVertex#298,id=$0,ts=$1)
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,565 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451565 end=1606457451565 duration=0
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: HiveProjectOverIntersectRemoveRule and HiveIntersectMerge rules>
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#302:HiveProject.HIVE.[](input=HepRelVertex#301,id=$0,ts=$1)
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451565 end=1606457451566 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: HiveIntersectRewrite rule>
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#305:HiveProject.HIVE.[](input=HepRelVertex#304,id=$0,ts=$1)
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,566 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451566 end=1606457451566 duration=0
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: HiveExceptRewrite rule>
2020-11-27T14:10:51,567 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,567 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#308:HiveProject.HIVE.[](input=HepRelVertex#307,id=$0,ts=$1)
2020-11-27T14:10:51,567 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,567 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451567 end=1606457451567 duration=0
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, factor out common filter elements and
separating deterministic vs non-deterministic UDF>
2020-11-27T14:10:51,568 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,568 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: call#11: Apply rule
[ReduceExpressionsRule(Project)] to
[rel#311:HiveProject.HIVE.[](input=HepRelVertex#310,id=$0,ts=$1)]
2020-11-27T14:10:51,579 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#311:HiveProject.HIVE.[](input=HepRelVertex#310,id=$0,ts=$1)
2020-11-27T14:10:51,579 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,580 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451567 end=1606457451580 duration=13
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, PPD, not null predicates, transitive
inference, constant folding>
2020-11-27T14:10:51,580 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,581 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#314:HiveProject.HIVE.[](input=HepRelVertex#313,id=$0,ts=$1)
2020-11-27T14:10:51,581 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,581 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451580 end=1606457451581 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, Push Down Semi Joins>
2020-11-27T14:10:51,581 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,581 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#317:HiveProject.HIVE.[](input=HepRelVertex#316,id=$0,ts=$1)
2020-11-27T14:10:51,582 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#291:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,582 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451581 end=1606457451582 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, Partition Pruning>
2020-11-27T14:10:51,582 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,592 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] calcite.sql2rel: Plan after trimming
unused fields
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,592 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451582 end=1606457451592 duration=10
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, Projection Pruning>
2020-11-27T14:10:51,592 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,593 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#322:HiveProject.HIVE.[](input=HepRelVertex#321,id=$0,ts=$1)
2020-11-27T14:10:51,593 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#319:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,593 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451592 end=1606457451593 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, Merge Project-Project>
2020-11-27T14:10:51,593 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,594 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#325:HiveProject.HIVE.[](input=HepRelVertex#324,id=$0,ts=$1)
2020-11-27T14:10:51,594 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#319:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,594 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451593 end=1606457451594 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Prejoin ordering transformation, Rerun PPD>
2020-11-27T14:10:51,596 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,596 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#328:HiveProject.HIVE.[](input=HepRelVertex#327,id=$0,ts=$1)
2020-11-27T14:10:51,597 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#319:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,597 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451596 end=1606457451597 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Optimizations without stats>
2020-11-27T14:10:51,597 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,597 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#331:HiveProject.HIVE.[](input=HepRelVertex#330,id=$0,ts=$1)
2020-11-27T14:10:51,598 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#319:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,598 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451597 end=1606457451598 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Semijoin conversion>
2020-11-27T14:10:51,598 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction>
2020-11-27T14:10:51,598 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#334:HiveProject.HIVE.[](input=HepRelVertex#333,id=$0,ts=$1)
2020-11-27T14:10:51,599 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] plan.RelOptPlanner: For final plan, using
rel#319:HiveTableScan.HIVE.[](table=[db.tb],table:alias=tb)[false]
2020-11-27T14:10:51,599 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451598 end=1606457451599 duration=1
from=org.apache.hadoop.hive.ql.parse.CalcitePlanner$CalcitePlannerAction
Calcite: Druid transformation rules>
2020-11-27T14:10:51,599 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: CBO Planning details:
2020-11-27T14:10:51,600 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Original Plan:
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,600 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Plan After PPD,
PartPruning, ColumnPruning:
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,610 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG
method=partition-retrieving
from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2020-11-27T14:10:51,610 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG
method=partition-retrieving start=1606457451610 end=1606457451610 duration=0
from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2020-11-27T14:10:51,628 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Plan After Join
Reordering:
HiveProject(id=[$0], ts=[$1]): rowcount = 1.0, cumulative cost = {0.0 rows,
0.0 cpu, 0.0 io}, id = 334
HiveTableScan(table=[[db.tb]], table:alias=[tb]): rowcount = 1.0,
cumulative cost = {0}, id = 319
2020-11-27T14:10:51,628 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] translator.PlanModifierForASTConv:
Original plan for PlanModifier
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,629 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] translator.PlanModifierForASTConv: Plan
after nested convertOpTree
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,629 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] translator.PlanModifierForASTConv: Plan
after propagating order
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,629 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] translator.PlanModifierForASTConv: Plan
after fixTopOBSchema
HiveProject(id=[$0], ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,629 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] translator.PlanModifierForASTConv: Final
plan after modifier
HiveProject(tb.id=[$0], tb.ts=[$1])
HiveTableScan(table=[[db.tb]], table:alias=[tb])
2020-11-27T14:10:51,630 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
source tables
2020-11-27T14:10:51,647 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
subqueries
2020-11-27T14:10:51,647 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Get metadata for
destination tables
2020-11-27T14:10:51,647 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#196
2020-11-27T14:10:51,648 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #196
2020-11-27T14:10:51,648 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getEZForPath took 1ms
2020-11-27T14:10:51,648 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: New scratch dir is
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] hive.log: DDL: struct tb { i32 id,
timestamp ts}
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] lazy.LazySerDeParameters:
org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe initialized with:
columnNames=[id, ts] columnTypes=[int, timestamp] separator=[[B@2b2f626f]
nullstring=\N lastColumnTakesRest=false timestampFormats=null
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Table Plan
for tb TS[0]
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: RR before GB
tb{(id,id: int)(ts,ts:
timestamp)(block__offset__inside__file,BLOCK__OFFSET__INSIDE__FILE:
bigint)(input__file__name,INPUT__FILE__NAME: string)(row__id,ROW__ID:
struct<transactionid:bigint,bucketid:int,rowid:bigint>)} after GB tb{(id,id:
int)(ts,ts: timestamp)(block__offset__inside__file,BLOCK__OFFSET__INSIDE__FILE:
bigint)(input__file__name,INPUT__FILE__NAME: string)(row__id,ROW__ID:
struct<transactionid:bigint,bucketid:int,rowid:bigint>)}
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: tree: (tok_select
(tok_selexpr (. (tok_table_or_col tb) id) tb.id) (tok_selexpr (.
(tok_table_or_col tb) ts) tb.ts))
2020-11-27T14:10:51,649 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: genSelectPlan: input
= tb{(id,id: int)(ts,ts:
timestamp)(block__offset__inside__file,BLOCK__OFFSET__INSIDE__FILE:
bigint)(input__file__name,INPUT__FILE__NAME: string)(row__id,ROW__ID:
struct<transactionid:bigint,bucketid:int,rowid:bigint>)} starRr = null
2020-11-27T14:10:51,650 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Select Plan
row schema: null{(tb.id,_col0: int)(tb.ts,_col1: timestamp)}
2020-11-27T14:10:51,650 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Select Plan
for clause: insclause-0
2020-11-27T14:10:51,651 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: Created staging dir =
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001/.hive-staging_hive_2020-11-27_14-10-51_478_1086002515739816328-1
for path =
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001
2020-11-27T14:10:51,651 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#197
2020-11-27T14:10:51,651 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #197
2020-11-27T14:10:51,652 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,653 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#198
2020-11-27T14:10:51,653 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #198
2020-11-27T14:10:51,653 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,654 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#199
2020-11-27T14:10:51,654 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #199
2020-11-27T14:10:51,654 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,655 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#200
2020-11-27T14:10:51,655 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #200
2020-11-27T14:10:51,655 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,655 DEBUG [HiveServer2-Handler-Pool: Thread-32]
hdfs.DFSClient:
/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001/.hive-staging_hive_2020-11-27_14-10-51_478_1086002515739816328-1:
masked=rwxr-xr-x
2020-11-27T14:10:51,656 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#201
2020-11-27T14:10:51,657 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #201
2020-11-27T14:10:51,657 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: mkdirs took 1ms
2020-11-27T14:10:51,657 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#202
2020-11-27T14:10:51,658 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #202
2020-11-27T14:10:51,658 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,658 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] shims.HdfsUtils:
{-chgrp,-R,supergroup,hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001}
2020-11-27T14:10:51,659 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#203
2020-11-27T14:10:51,659 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #203
2020-11-27T14:10:51,660 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 0ms
2020-11-27T14:10:51,660 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#204
2020-11-27T14:10:51,661 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #204
2020-11-27T14:10:51,661 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,661 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#205
2020-11-27T14:10:51,662 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #205
2020-11-27T14:10:51,662 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,662 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] shims.HdfsUtils: Return value is :0
2020-11-27T14:10:51,662 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] shims.HdfsUtils:
{-chmod,-R,700,hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001}
2020-11-27T14:10:51,663 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#206
2020-11-27T14:10:51,663 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #206
2020-11-27T14:10:51,663 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,664 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#207
2020-11-27T14:10:51,665 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #207
2020-11-27T14:10:51,666 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: setPermission took 2ms
2020-11-27T14:10:51,666 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#208
2020-11-27T14:10:51,667 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #208
2020-11-27T14:10:51,667 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,667 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#209
2020-11-27T14:10:51,668 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #209
2020-11-27T14:10:51,668 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: setPermission took 1ms
2020-11-27T14:10:51,668 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#210
2020-11-27T14:10:51,669 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #210
2020-11-27T14:10:51,669 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,669 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] shims.HdfsUtils: Return value is :0
2020-11-27T14:10:51,670 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#211
2020-11-27T14:10:51,671 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #211
2020-11-27T14:10:51,671 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 2ms
2020-11-27T14:10:51,671 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] lazy.LazySerDeParameters:
org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe initialized with:
columnNames=[_col0, _col1] columnTypes=[int, timestamp] separator=[[B@40ac0d3b]
nullstring=\N lastColumnTakesRest=false timestampFormats=null
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Set stats collection
dir :
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001/.hive-staging_hive_2020-11-27_14-10-51_478_1086002515739816328-1/-ext-10003
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created FileSink
Plan for clause: insclause-0dest_path:
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001
row schema: null{(tb.id,_col0: int)(tb.ts,_col1: timestamp)}
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Body Plan
for Query Block null
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Created Plan for
Query Block null
2020-11-27T14:10:51,672 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: CBO Succeeded;
optimized logical plan.
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Before logical
optimization
TS[0]-SEL[1]-FS[2]
2020-11-27T14:10:51,672 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.calcite.translator.HiveOpConverterPostProc>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451672 end=1606457451672 duration=0
from=org.apache.hadoop.hive.ql.optimizer.calcite.translator.HiveOpConverterPostProc
org.apache.hadoop.hive.ql.optimizer.calcite.translator.HiveOpConverterPostProc@760b4478>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.PartitionColumnsSeparator>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451673 end=1606457451673 duration=0
from=org.apache.hadoop.hive.ql.optimizer.PartitionColumnsSeparator
org.apache.hadoop.hive.ql.optimizer.PartitionColumnsSeparator@5d48eed>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.ppd.SyntheticJoinPredicate>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451673 end=1606457451673 duration=0
from=org.apache.hadoop.hive.ql.ppd.SyntheticJoinPredicate
org.apache.hadoop.hive.ql.ppd.SyntheticJoinPredicate@6a477d49>
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.ppd.SimplePredicatePushDown>
2020-11-27T14:10:51,673 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ppd.OpProcFactory: Processing for FS(2)
2020-11-27T14:10:51,673 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ppd.OpProcFactory: Processing for SEL(1)
2020-11-27T14:10:51,673 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ppd.OpProcFactory: Processing for TS(0)
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ppd.SimplePredicatePushDown: After PPD:
TS[0]-SEL[1]-FS[2]
2020-11-27T14:10:51,673 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451673 end=1606457451673 duration=0
from=org.apache.hadoop.hive.ql.ppd.SimplePredicatePushDown
org.apache.hadoop.hive.ql.ppd.SimplePredicatePushDown@72158335>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.RedundantDynamicPruningConditionsRemoval>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451673 end=1606457451674 duration=1
from=org.apache.hadoop.hive.ql.optimizer.RedundantDynamicPruningConditionsRemoval
org.apache.hadoop.hive.ql.optimizer.RedundantDynamicPruningConditionsRemoval@7d746fb2>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.SortedDynPartitionTimeGranularityOptimizer>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451674 end=1606457451674 duration=0
from=org.apache.hadoop.hive.ql.optimizer.SortedDynPartitionTimeGranularityOptimizer
org.apache.hadoop.hive.ql.optimizer.SortedDynPartitionTimeGranularityOptimizer@1726619d>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451674 end=1606457451674 duration=0
from=org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner
org.apache.hadoop.hive.ql.optimizer.ppr.PartitionPruner@489d27e2>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.pcr.PartitionConditionRemover>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451674 end=1606457451674 duration=0
from=org.apache.hadoop.hive.ql.optimizer.pcr.PartitionConditionRemover
org.apache.hadoop.hive.ql.optimizer.pcr.PartitionConditionRemover@7af2b6c>
2020-11-27T14:10:51,674 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.GroupByOptimizer>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451674 end=1606457451675 duration=1
from=org.apache.hadoop.hive.ql.optimizer.GroupByOptimizer
org.apache.hadoop.hive.ql.optimizer.GroupByOptimizer@2cddcf68>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.ColumnPruner>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451675 end=1606457451675 duration=0
from=org.apache.hadoop.hive.ql.optimizer.ColumnPruner
org.apache.hadoop.hive.ql.optimizer.ColumnPruner@7cec34e2>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.SamplePruner>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451675 end=1606457451675 duration=0
from=org.apache.hadoop.hive.ql.optimizer.SamplePruner
org.apache.hadoop.hive.ql.optimizer.SamplePruner@65557583>
2020-11-27T14:10:51,675 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.MapJoinProcessor>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451675 end=1606457451675 duration=0
from=org.apache.hadoop.hive.ql.optimizer.MapJoinProcessor
org.apache.hadoop.hive.ql.optimizer.MapJoinProcessor@589f86ea>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.BucketingSortingReduceSinkOptimizer>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451676 end=1606457451676 duration=0
from=org.apache.hadoop.hive.ql.optimizer.BucketingSortingReduceSinkOptimizer
org.apache.hadoop.hive.ql.optimizer.BucketingSortingReduceSinkOptimizer@449fb42c>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.unionproc.UnionProcessor>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451676 end=1606457451676 duration=0
from=org.apache.hadoop.hive.ql.optimizer.unionproc.UnionProcessor
org.apache.hadoop.hive.ql.optimizer.unionproc.UnionProcessor@31115d>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.JoinReorder>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451676 end=1606457451676 duration=0
from=org.apache.hadoop.hive.ql.optimizer.JoinReorder
org.apache.hadoop.hive.ql.optimizer.JoinReorder@5c034950>
2020-11-27T14:10:51,676 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.correlation.ReduceSinkDeDuplication>
2020-11-27T14:10:51,677 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451676 end=1606457451677 duration=1
from=org.apache.hadoop.hive.ql.optimizer.correlation.ReduceSinkDeDuplication
org.apache.hadoop.hive.ql.optimizer.correlation.ReduceSinkDeDuplication@416212aa>
2020-11-27T14:10:51,677 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.NonBlockingOpDeDupProc>
2020-11-27T14:10:51,677 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451677 end=1606457451677 duration=0
from=org.apache.hadoop.hive.ql.optimizer.NonBlockingOpDeDupProc
org.apache.hadoop.hive.ql.optimizer.NonBlockingOpDeDupProc@68aaa904>
2020-11-27T14:10:51,677 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.IdentityProjectRemover>
2020-11-27T14:10:51,677 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451677 end=1606457451677 duration=0
from=org.apache.hadoop.hive.ql.optimizer.IdentityProjectRemover
org.apache.hadoop.hive.ql.optimizer.IdentityProjectRemover@525ac9a5>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.LimitPushdownOptimizer>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451677 end=1606457451678 duration=1
from=org.apache.hadoop.hive.ql.optimizer.LimitPushdownOptimizer
org.apache.hadoop.hive.ql.optimizer.LimitPushdownOptimizer@176618ba>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.StatsOptimizer>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451678 end=1606457451678 duration=0
from=org.apache.hadoop.hive.ql.optimizer.StatsOptimizer
org.apache.hadoop.hive.ql.optimizer.StatsOptimizer@55c3fc51>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: <PERFLOG method=optimizer
from=org.apache.hadoop.hive.ql.optimizer.SimpleFetchOptimizer>
2020-11-27T14:10:51,678 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] hive.log: DDL: struct tb { i32 id,
timestamp ts}
2020-11-27T14:10:51,679 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=optimizer
start=1606457451678 end=1606457451678 duration=0
from=org.apache.hadoop.hive.ql.optimizer.SimpleFetchOptimizer
org.apache.hadoop.hive.ql.optimizer.SimpleFetchOptimizer@72478d9b>
2020-11-27T14:10:51,679 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: After logical
optimization
TS[0]-SEL[1]-LIST_SINK[3]
2020-11-27T14:10:51,679 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: Completed plan
generation
2020-11-27T14:10:51,679 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Driver: Semantic Analysis Completed
2020-11-27T14:10:51,679 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: validation start
2020-11-27T14:10:51,679 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] parse.CalcitePlanner: not validating
writeEntity, because entity is neither table nor partition
2020-11-27T14:10:51,679 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG
method=semanticAnalyze start=1606457451479 end=1606457451679 duration=200
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,679 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Driver: Returning Hive schema:
Schema(fieldSchemas:[FieldSchema(name:tb.id, type:int, comment:null),
FieldSchema(name:tb.ts, type:timestamp, comment:null)], properties:null)
2020-11-27T14:10:51,680 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] lazy.LazySerDeParameters:
org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe initialized with:
columnNames=[id, ts] columnTypes=[int, timestamp] separator=[[B@5a4708b8]
nullstring=\N lastColumnTakesRest=false timestampFormats=null
2020-11-27T14:10:51,680 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Initializing
operator TS[0]
2020-11-27T14:10:51,680 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Initialization
Done 0 TS
2020-11-27T14:10:51,680 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Operator 0 TS
initialized
2020-11-27T14:10:51,680 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Initializing
children of 0 TS
2020-11-27T14:10:51,680 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Initializing child 1
SEL
2020-11-27T14:10:51,680 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Initializing operator
SEL[1]
2020-11-27T14:10:51,680 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: SELECT
struct<id:int,ts:timestamp>
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Initialization Done 1
SEL
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Operator 1 SEL
initialized
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Initializing children
of 1 SEL
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Initializing child
3 LIST_SINK
2020-11-27T14:10:51,681 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Initializing
operator LIST_SINK[3]
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Initialization Done
3 LIST_SINK
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Operator 3
LIST_SINK initialized
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Initialization Done
3 LIST_SINK done is reset.
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Initialization Done 1
SEL done is reset.
2020-11-27T14:10:51,681 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Initialization
Done 0 TS done is reset.
2020-11-27T14:10:51,682 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] log.PerfLogger: </PERFLOG method=compile
start=1606457451478 end=1606457451681 duration=203
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,682 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] metadata.Hive: Dumping metastore api call
timing information for : compilation phase
2020-11-27T14:10:51,682 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] metadata.Hive: Total time spent in each
metastore function (ms): {isCompatibleWith_(HiveConf, )=0, getTable_(String,
String, )=64, flushCache_()=0}
2020-11-27T14:10:51,682 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Driver: Completed compiling
command(queryId=dovezhang_20201127141051_08c245d8-c816-41fb-8d0a-4f06d6e2b50d);
Time taken: 0.203 seconds
2020-11-27T14:10:51,683 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,683 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: SessionHandle [0dbe373c-c442-49f2-ad5e-e65735d41988]:
executeStatementAsync()
2020-11-27T14:10:51,683 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 109
2020-11-27T14:10:51,684 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 104
2020-11-27T14:10:51,684 INFO [HiveServer2-Background-Pool: Thread-73]
ql.Driver: Concurrency mode is disabled, not creating a lock manager
2020-11-27T14:10:51,684 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: <PERFLOG method=Driver.execute
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,684 INFO [HiveServer2-Background-Pool: Thread-73]
ql.Driver: Executing
command(queryId=dovezhang_20201127141051_08c245d8-c816-41fb-8d0a-4f06d6e2b50d):
select * from db.tb
2020-11-27T14:10:51,866 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: <PERFLOG method=runTasks from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,866 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: </PERFLOG method=runTasks start=1606457451866 end=1606457451866
duration=0 from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,866 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: </PERFLOG method=Driver.execute start=1606457451684
end=1606457451866 duration=182 from=org.apache.hadoop.hive.ql.Driver>
OK
2020-11-27T14:10:51,866 INFO [HiveServer2-Background-Pool: Thread-73]
metadata.Hive: Dumping metastore api call timing information for : execution
phase
2020-11-27T14:10:51,867 DEBUG [HiveServer2-Background-Pool: Thread-73]
metadata.Hive: Total time spent in each metastore function (ms): {}
2020-11-27T14:10:51,867 INFO [HiveServer2-Background-Pool: Thread-73]
ql.Driver: Completed executing
command(queryId=dovezhang_20201127141051_08c245d8-c816-41fb-8d0a-4f06d6e2b50d);
Time taken: 0.182 seconds
2020-11-27T14:10:51,867 INFO [HiveServer2-Background-Pool: Thread-73]
ql.Driver: OK
2020-11-27T14:10:51,867 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: <PERFLOG method=releaseLocks
from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,867 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: </PERFLOG method=releaseLocks start=1606457451867
end=1606457451867 duration=0 from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,867 DEBUG [HiveServer2-Background-Pool: Thread-73]
log.PerfLogger: </PERFLOG method=Driver.run start=1606457451478
end=1606457451867 duration=389 from=org.apache.hadoop.hive.ql.Driver>
2020-11-27T14:10:51,867 DEBUG [HiveServer2-Background-Pool: Thread-73]
ql.Driver: Shutting down query select * from db.tb
2020-11-27T14:10:51,870 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]:
getOperationStatus()
2020-11-27T14:10:51,870 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 144
2020-11-27T14:10:51,871 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 102
2020-11-27T14:10:51,872 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,872 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,872 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]:
getResultSetMetadata()
2020-11-27T14:10:51,872 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 148
2020-11-27T14:10:51,874 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 117
2020-11-27T14:10:51,874 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,875 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,875 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]: fetchResults()
2020-11-27T14:10:51,875 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 96
2020-11-27T14:10:51,876 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 112
2020-11-27T14:10:51,876 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,877 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#212
2020-11-27T14:10:51,877 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #212
2020-11-27T14:10:51,877 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getFileInfo took 1ms
2020-11-27T14:10:51,878 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#213
2020-11-27T14:10:51,878 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #213
2020-11-27T14:10:51,878 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,879 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#214
2020-11-27T14:10:51,879 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #214
2020-11-27T14:10:51,879 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: getListing took 1ms
2020-11-27T14:10:51,879 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: close called for
operator TS[0]
2020-11-27T14:10:51,880 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Closing operator
TS[0]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: Closing child =
SEL[1]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: close called for
operator SEL[1]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator:
allInitializedParentsAreClosed? parent.state = CLOSE
2020-11-27T14:10:51,880 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Closing operator
SEL[1]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: Closing child =
LIST_SINK[3]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: close called for
operator LIST_SINK[3]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator:
allInitializedParentsAreClosed? parent.state = CLOSE
2020-11-27T14:10:51,880 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: Closing operator
LIST_SINK[3]
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.ListSinkOperator: 3 Close done
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.SelectOperator: 1 Close done
2020-11-27T14:10:51,880 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] exec.TableScanOperator: 0 Close done
2020-11-27T14:10:51,881 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,881 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]: fetchResults()
2020-11-27T14:10:51,881 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 117
2020-11-27T14:10:51,882 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 112
2020-11-27T14:10:51,882 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,882 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,882 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]: fetchResults()
2020-11-27T14:10:51,882 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 117
2020-11-27T14:10:51,883 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 117
2020-11-27T14:10:51,883 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,884 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,884 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]: fetchResults()
2020-11-27T14:10:51,884 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 96
2020-11-27T14:10:51,884 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: SERVER: reading data length: 96
2020-11-27T14:10:51,884 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Updating thread name to
0dbe373c-c442-49f2-ad5e-e65735d41988 HiveServer2-Handler-Pool: Thread-32
2020-11-27T14:10:51,885 INFO [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] operation.OperationManager: Closing
operation: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]
2020-11-27T14:10:51,885 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: Deleting result dir:
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001
2020-11-27T14:10:51,885 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#215
2020-11-27T14:10:51,888 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #215
2020-11-27T14:10:51,888 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: delete took 3ms
2020-11-27T14:10:51,888 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: Deleting scratch dir:
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1/-mr-10001/.hive-staging_hive_2020-11-27_14-10-51_478_1086002515739816328-1
2020-11-27T14:10:51,888 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#216
2020-11-27T14:10:51,889 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #216
2020-11-27T14:10:51,889 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: delete took 1ms
2020-11-27T14:10:51,889 DEBUG [0dbe373c-c442-49f2-ad5e-e65735d41988
HiveServer2-Handler-Pool: Thread-32] ql.Context: Deleting scratch dir:
hdfs://localhost:8020/usr/hive/scratchdir/hive/0dbe373c-c442-49f2-ad5e-e65735d41988/hive_2020-11-27_14-10-51_478_1086002515739816328-1
2020-11-27T14:10:51,889 DEBUG [IPC Parameter Sending Thread #5] ipc.Client:
IPC Client (188791662) connection to localhost/127.0.0.1:8020 from hive sending
#217
2020-11-27T14:10:51,890 DEBUG [IPC Client (188791662) connection to
localhost/127.0.0.1:8020 from hive] ipc.Client: IPC Client (188791662)
connection to localhost/127.0.0.1:8020 from hive got value #217
2020-11-27T14:10:51,890 DEBUG [HiveServer2-Handler-Pool: Thread-32]
ipc.ProtobufRpcEngine: Call: delete took 1ms
2020-11-27T14:10:51,891 INFO [HiveServer2-Handler-Pool: Thread-32]
session.SessionState: Resetting thread name to HiveServer2-Handler-Pool:
Thread-32
2020-11-27T14:10:51,891 DEBUG [HiveServer2-Handler-Pool: Thread-32]
cli.CLIService: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=84ff9912-e1db-4722-8a18-5a0543f6b1bd]: closeOperation
2020-11-27T14:10:51,891 DEBUG [HiveServer2-Handler-Pool: Thread-32]
transport.TSaslTransport: writing data length: 42
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
