search

apache / iceberg

Apache Iceberg
https://iceberg.apache.org/
Apache License 2.0
6.34k stars 2.19k forks source link

Hive: create and write iceberg by hive catalog using Spark, Hive client read no data #1831

Closed zhangdove closed 3 years ago

zhangdove commented 3 years ago

  1. Environment

    spark: 3.0.0
hive: 2.3.7
iceberg: 0.10.0

  2. SparkSession configuration

    val spark = SparkSession
  .builder()
  .master("local[2]")
  .appName("IcebergAPI")
  .config("spark.sql.catalog.hive_prod", "org.apache.iceberg.spark.SparkCatalog")
  .config("spark.sql.catalog.hive_prod.type", "hive")
  .config("spark.sql.catalog.hive_prod.uri", "thrift://localhost:9083")
  .enableHiveSupport()
  .getOrCreate()

  3. Create database db by hive client

    ➜  bin ./beeline
beeline> !connect jdbc:hive2://localhost:10000 hive hive
Connecting to jdbc:hive2://localhost:10000
Connected to: Apache Hive (version 2.3.7)
Driver: Hive JDBC (version 2.3.7)
Transaction isolation: TRANSACTION_REPEATABLE_READ
0: jdbc:hive2://localhost:10000> create database db;
No rows affected (0.105 seconds)

  4. Create iceberg table by hiveCatalog using Spark (Link: https://iceberg.apache.org/hive/#using-hive-catalog)

    def createByHiveCatalog(spark: SparkSession): Unit = {
val hadoopConfiguration = spark.sparkContext.hadoopConfiguration
hadoopConfiguration.set(org.apache.iceberg.hadoop.ConfigProperties.ENGINE_HIVE_ENABLED, "true"); //iceberg.engine.hive.enabled=true
val hiveCatalog = new HiveCatalog(hadoopConfiguration)
val nameSpace = Namespace.of("db")
val tableIdentifier: TableIdentifier = TableIdentifier.of(nameSpace, "tb")

val columns: List[Types.NestedField] = new ArrayList[Types.NestedField]
columns.add(Types.NestedField.of(1, true, "id", Types.IntegerType.get, "id doc"))
columns.add(Types.NestedField.of(2, true, "ts", Types.TimestampType.withZone(), "ts doc"))

val schema: Schema = new Schema(columns)
val partition = PartitionSpec.builderFor(schema).year("ts").build()

hiveCatalog.createTable(tableIdentifier, schema, partition)
}

  5. Query iceberg table by hive client

    0: jdbc:hive2://localhost:10000> add jar /Users/dovezhang/software/idea/github/iceberg/hive-runtime/build/libs/iceberg-hive-runtime-0.10.0.jar;
No rows affected (0.043 seconds)
0: jdbc:hive2://localhost:10000> set iceberg.mr.catalog=hive;
No rows affected (0.003 seconds)
0: jdbc:hive2://localhost:10000> select * from db.tb;
+--------+--------+
| tb.id  | tb.ts  |
+--------+--------+
+--------+--------+
No rows selected (1.166 seconds)

  6. Write data by hive Catalog using Spark

    case class dbtb(id: Int, time: Timestamp)
def writeDataToIcebergHive(spark: SparkSession): Unit = {
val seq = Seq(dbtb(1, Timestamp.valueOf("2020-07-06 13:40:00")),
  dbtb(2, Timestamp.valueOf("2020-07-06 14:30:00")),
  dbtb(3, Timestamp.valueOf("2020-07-06 15:20:00")))
val df = spark.createDataFrame(seq).toDF("id", "ts")

import org.apache.spark.sql.functions
df.writeTo(s"hive_prod.db.tb").overwrite(functions.lit(true))
}

  7. Query iceberg table by hive client

    0: jdbc:hive2://localhost:10000> select * from db.tb;
+--------+--------+
| tb.id  | tb.ts  |
+--------+--------+
+--------+--------+
No rows selected (0.152 seconds)

    After writing the data, no data is returned via Hive Client.

  8. Query iceberg table by hive catalog using Spark

    def readIcebergByHiveCatalog(spark: SparkSession): Unit = {
spark.sql("select * from hive_prod.db.tb").show(false)
}

    Result

    +---+-------------------+
|id |ts                 |
+---+-------------------+
|1  |2020-07-06 13:40:00|
|2  |2020-07-06 14:30:00|
|3  |2020-07-06 15:20:00|
+---+-------------------+

  9. Check the table of contents for data files

    ➜  bin hdfs dfs -ls /usr/hive/warehouse/db.db/tb/data/ts_year=2020
20/11/26 15:16:51 WARN util.NativeCodeLoader: Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
Found 2 items
-rw-r--r--   1 dovezhang supergroup        656 2020-11-26 15:11 /usr/hive/warehouse/db.db/tb/data/ts_year=2020/00000-0-2b98be41-8347-4a8c-a986-d28878ab7a67-00001.parquet
-rw-r--r--   1 dovezhang supergroup        664 2020-11-26 15:11 /usr/hive/warehouse/db.db/tb/data/ts_year=2020/00001-1-b192e846-5a6a-4ee9-b31a-7e5fcf813b88-00001.parquet

I am not sure why the Hive Client cannot see data after Spark builds tables and writes data. Have anyone know it?

pvary commented 3 years ago

@zhangdove: Could you please share the HiveServer2 logs for the SELECT * FROM db.tb query? Maybe even DEBUG level logs, if possible. Also the results of the DESCRIBE FORMATTED db.tb command from BeeLine might help? Thanks, Peter

zhangdove commented 3 years ago

@pvary The DEBUG log information of HiveServer2 is quite large, so I haven't found any useful logs yet. I will make a further investigation later.

And there is DESCRIBE FORMATTED db.tb

0: jdbc:hive2://localhost:10000> DESCRIBE FORMATTED db.tb;
OK
+-------------------------------+----------------------------------------------------+----------------------------------------------------+
|           col_name            |                     data_type                      |                      comment                       |
+-------------------------------+----------------------------------------------------+----------------------------------------------------+
| # col_name                    | data_type                                          | comment                                            |
|                               | NULL                                               | NULL                                               |
| id                            | int                                                |                                                    |
| ts                            | timestamp                                          |                                                    |
|                               | NULL                                               | NULL                                               |
| # Detailed Table Information  | NULL                                               | NULL                                               |
| Database:                     | db                                                 | NULL                                               |
| Owner:                        | dovezhang                                          | NULL                                               |
| CreateTime:                   | Thu Nov 26 17:56:31 CST 2020                       | NULL                                               |
| LastAccessTime:               | Fri Jan 02 02:33:42 CST 1970                       | NULL                                               |
| Retention:                    | 2147483647                                         | NULL                                               |
| Location:                     | hdfs://localhost:8020/usr/hive/warehouse/db.db/tb  | NULL                                               |
| Table Type:                   | EXTERNAL_TABLE                                     | NULL                                               |
| Table Parameters:             | NULL                                               | NULL                                               |
|                               | EXTERNAL                                           | TRUE                                               |
|                               | metadata_location                                  | hdfs://localhost:8020/usr/hive/warehouse/db.db/tb/metadata/00001-ffce82b8-fba2-4681-b095-67f472653333.metadata.json |
|                               | numFiles                                           | 3                                                  |
|                               | previous_metadata_location                         | hdfs://localhost:8020/usr/hive/warehouse/db.db/tb/metadata/00000-3c8cce22-19c5-4926-9da5-9bf6cd9cc0f8.metadata.json |
|                               | table_type                                         | ICEBERG                                            |
|                               | totalSize                                          | 3195                                               |
|                               | transient_lastDdlTime                              | 1606384591                                         |
|                               | NULL                                               | NULL                                               |
| # Storage Information         | NULL                                               | NULL                                               |
| SerDe Library:                | org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe | NULL                                               |
| InputFormat:                  | org.apache.hadoop.mapred.FileInputFormat           | NULL                                               |
| OutputFormat:                 | org.apache.hadoop.mapred.FileOutputFormat          | NULL                                               |
| Compressed:                   | No                                                 | NULL                                               |
| Num Buckets:                  | 0                                                  | NULL                                               |
| Bucket Columns:               | []                                                 | NULL                                               |
| Sort Columns:                 | []                                                 | NULL                                               |
+-------------------------------+----------------------------------------------------+----------------------------------------------------+
30 rows selected (0.14 seconds)
zhangdove commented 3 years ago 
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
zhangdove commented 3 years ago

@pvary Start HiveServer2 by bin/hiveserver2 --hiveconf hive.root.logger=DEBUG,console, and the above information is the log information when 'select * from db.tb' is made.

I'm not sure if I configured the environment the wrong way, I didn't find the information I wanted from this pile of logs.

zhangdove commented 3 years ago

@pvary And the strange thing is that In this issue-comment, I used the HadoopCatalog to create a table, write data, and then read it in the way of Hive external table, and the result could be returned normally.

pvary commented 3 years ago

@zhangdove: The main problem is this:

| SerDe Library:                | org.apache.hadoop.hive.serde2.lazy.LazySimpleSerDe | NULL                                               |
| InputFormat:                  | org.apache.hadoop.mapred.FileInputFormat           | NULL                                               |
| OutputFormat:                 | org.apache.hadoop.mapred.FileOutputFormat          | NULL                                               |

Somehow the SerDe is not set. We should find out why the following line is not working:

    hadoopConfiguration.set(org.apache.iceberg.hadoop.ConfigProperties.ENGINE_HIVE_ENABLED, "true"); //iceberg.engine.hive.enabled=true
pvary commented 3 years ago

There might be some issue with the table properties:

  private static boolean hiveEngineEnabled(TableMetadata metadata, Configuration conf) {
    if (metadata.properties().get(TableProperties.ENGINE_HIVE_ENABLED) != null) {
      // We know that the property is set, so default value will not be used,
      return metadata.propertyAsBoolean(TableProperties.ENGINE_HIVE_ENABLED, false);
    }

    return conf.getBoolean(ConfigProperties.ENGINE_HIVE_ENABLED, TableProperties.ENGINE_HIVE_ENABLED_DEFAULT);
  }

Could we check the metadata value for TableProperties.ENGINE_HIVE_ENABLED?

Thanks, Peter

zhangdove commented 3 years ago

@pvary Thank you for the information you provided. Based on the information you provided, I made a survey and found the following.

Iceberg table is created using the Hive Catalog. The properties of the table are normal:

| SerDe Library:                | org.apache.iceberg.mr.hive.HiveIcebergSerDe        | NULL                                               |
| InputFormat:                  | null                                               | NULL                                               |
| OutputFormat:                 | null                                               | NULL                                               |

However, when I write data to Iceberg, as follows, the SerDe properties of the table have been modified.

    df.writeTo(s"hive_prod.db.tb").overwrite(functions.lit(true))
    df.writeTo(s"hive_prod.db.tb").overwritePartitions()
    df.writeTo(s"hive_prod.db.tb").append()

I am still learning this module of Hive, so I am not familiar with it. I have two ideas that are less than exact: a) Save the value of TableProperties.ENGINE_HIVE_ENABLED. I am not suer whether the property will be reloaded when iceberg is written to use Spark. b) Set the TableProperties.ENGINE_HIVE_ENABLED property to true when building the Hive Catalog and add it to conf. https://github.com/apache/iceberg/blob/master/spark3/src/main/java/org/apache/iceberg/spark/SparkCatalog.java#L114

I will do some tests next, but I hope to get feedback from the everyone if possible.

pvary commented 3 years ago

Could it be that the iceberg.engine.hive.enabled is only changed in the config at creation time? It it is not set when we overwrite the data then the new snapshot might remove these values. If we set it on the table properties then it might help

rdblue commented 3 years ago

I think @pvary is right: the property may not be set when the write happens and that causes the serde to get reset to the generic one. I think the right thing to do is to configure either hive-site.xml (or make sure the config is consistent in Spark) or to set the table property, which will ensure Hive support is always enabled.

GintokiYs commented 3 years ago

The property engine.hive.enabled needs to be set to true and added to the table properties when creating the Iceberg table.

Map<String, String> tableProperties = new HashMap<String, String>(); 
tableProperties.put(TableProperties.ENGINE_HIVE_ENABLED, "true"); //engine.hive.enabled=true 
catalog.createTable(tableId, schema, spec, tableProperties);

You may can refer to the Using Hive Catalog module of this article. https://iceberg.apache.org/hive/#using-hive-catalog

zhangdove commented 3 years ago

Thanks for all reply. Modify the usage to work properly.