Thank you for your response.
I understand that even if Hive and Trino use the same Hive Metastore as a
Catalog, additional implementation in TrinoCatalog is necessary to ensure
data correctness.
To clarify, the deadlock issue I am referring to is not a situation where
the IOW lock cannot be obtained, rather this is a case where the StatsTask
cannot acquire the commitLock due to IOW lock.
I've applied the following settings to utilize the pessimistic locking
added in HIVE-28366 for Iceberg tables:
```
set hive.support.concurrency=true;
set hive.txn.ext.locking.enabled=true;
set hive.txn.manager=org.apache.hadoop.hive.ql.lockmgr.DbTxnManager;
set iceberg.engine.hive.lock-enabled=false;
```
After applying these settings, I've run a simple INSERT query:
```
create table ice_t (i int) stored by iceberg;
insert into ice_t values (1);
```
By doing so, I observed that the intended pessimistic lock was indeed
acquired; however, during the preAlterTable (HiveIcebergMetaHook) process
in StatsTask, commitLock stays in a wait state.
In the HIVE_LOCKS table of Metastore DB(Mysql), I found the following locks:
```
+----------------+----------------+----------+-------------------------------+------------------------+--------------+---------------+--------------+-------------------+----------------+-------------------------------------------+----------+--------------------+----------------------------------------------------------+---------------------+---------------------+
| HL_LOCK_EXT_ID | HL_LOCK_INT_ID | HL_TXNID | HL_DB
| HL_TABLE | HL_PARTITION | HL_LOCK_STATE | HL_LOCK_TYPE |
HL_LAST_HEARTBEAT | HL_ACQUIRED_AT | HL_USER
| HL_HOST | HL_HEARTBEAT_COUNT | HL_AGENT_INFO
| HL_BLOCKEDBY_EXT_ID | HL_BLOCKEDBY_INT_ID |
+----------------+----------------+----------+-------------------------------+------------------------+--------------+---------------+--------------+-------------------+----------------+-------------------------------------------+----------+--------------------+----------------------------------------------------------+---------------------+---------------------+
| 110 | 1 | 0 | default
| ice_t | NULL | a | w |
1743047445606 | 1743047445606 | hadoop-admin
| owen-rm3 | NULL |
hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4 |
NULL | NULL |
| 111 | 1 | 0 | default
| ice_t | NULL | w | x |
1743047462328 | NULL | hadoop-admin
| owen-rm3 | NULL |
Iceberg-df6861e6-8e49-4cac-a2a8-2d0362a8d535 |
110 | 1 |
+----------------+----------------+----------+-------------------------------+------------------------+--------------+---------------+--------------+-------------------+----------------+-------------------------------------------+----------+--------------------+----------------------------------------------------------+---------------------+---------------------+
```
Eventually, the StatsTask fails due to lock timeout.
This occurrence has been happening since the change in the LOCK_TYPE of
HiveIcebergStorageHandler in HIVE-28366.
Can you please confirm if this situation represents a bug?
I've attached the HIVE SERVER2 logs for your reference.
Thank you for your assistance.
Regards, Owen
2025-03-27T12:50:45,255 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] session.HiveSessionImpl: executing insert
into ice_t values (1)
2025-03-27T12:50:45,258 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.OperationManager: Adding
operation: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=fd31c8f8-662b-44c0-9971-8d9998098703] SessionHandle
[59fba971-a3aa-4d11-87e9-c2d3b96a491c]
2025-03-27T12:50:45,258 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:45,259 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.SQLOperation:
[opType=EXECUTE_STATEMENT,
queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4,
startTime=1743047445256, sessionId=59fba971-a3aa-4d11-87e9-c2d3b96a491c,
createTime=1743046954375, userName=hadoop-admin, ipAddress=...]
2025-03-27T12:50:45,262 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] reexec.ReExecDriver: Compile #1 of query
2025-03-27T12:50:45,263 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Driver: Compiling
command(queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4):
insert into ice_t values (1)
2025-03-27T12:50:45,271 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.QueryState: Query-level HMS cache
created for hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:50:45,271 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Starting Semantic
Analysis
2025-03-27T12:50:45,389 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] iceberg.BaseMetastoreTableOperations:
Refreshing table metadata from new version:
hdfs://owen/user/hive/warehouse/ice_t/metadata/00000-8073025d-2cd5-42f4-82d7-ad9b983e85ac.metadata.json
2025-03-27T12:50:45,394 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] iceberg.BaseMetastoreCatalog: Table loaded
by catalog: default_iceberg.default.ice_t
2025-03-27T12:50:45,395 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] hive.HiveIcebergSerDe: Using schema from
existing table
{"type":"struct","schema-id":0,"fields":[{"id":1,"name":"i","required":false,"type":"int"}]}
2025-03-27T12:50:45,395 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Completed phase 1 of
Semantic Analysis
2025-03-27T12:50:45,395 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
source tables
2025-03-27T12:50:45,395 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
subqueries
2025-03-27T12:50:45,395 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
destination tables
2025-03-27T12:50:45,396 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Completed getting
MetaData in Semantic Analysis
2025-03-27T12:50:45,396 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Disabling LLAP IO
encode as ETL query is detected
2025-03-27T12:50:45,412 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Context: New scratch dir is
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:50:45,528 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
source tables
2025-03-27T12:50:45,528 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
subqueries
2025-03-27T12:50:45,529 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
source tables
2025-03-27T12:50:45,539 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
subqueries
2025-03-27T12:50:45,539 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
destination tables
2025-03-27T12:50:45,539 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Get metadata for
destination tables
2025-03-27T12:50:45,545 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] hive.HiveIcebergSerDe: Using schema from
existing table
{"type":"struct","schema-id":0,"fields":[{"id":1,"name":"i","required":false,"type":"int"}]}
2025-03-27T12:50:45,557 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] common.FileUtils: Creating directory if it
doesn't exist:
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:50:45,566 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: CBO Succeeded;
optimized logical plan.
2025-03-27T12:50:45,569 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] optimizer.BucketVersionPopulator: not
considering bucketingVersion for: TS[0] because it has -1<2 buckets
2025-03-27T12:50:45,573 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] optimizer.SortedDynPartitionOptimizer:
Sorted dynamic partitioning optimization kicked in..
2025-03-27T12:50:45,574 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] optimizer.BucketVersionPopulator: not
considering bucketingVersion for: TS[0] because it has -1<2 buckets
2025-03-27T12:50:45,574 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.TezCompiler: Cycle free: true
2025-03-27T12:50:45,574 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] optimizer.SharedWorkOptimizer:
SharedWorkOptimizer start
2025-03-27T12:50:45,576 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.GenTezUtils: using
CombineHiveInputformat for the merge job
2025-03-27T12:50:45,578 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] parse.CalcitePlanner: Completed plan
generation
2025-03-27T12:50:45,578 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Driver: Semantic Analysis Completed
(retrial = false)
2025-03-27T12:50:45,578 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Driver: Created Hive schema:
Schema(fieldSchemas:[FieldSchema(name:col1, type:int, comment:null)],
properties:null)
2025-03-27T12:50:45,586 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] metadata.Hive: Dumping metastore api call
timing information for : compilation phase
2025-03-27T12:50:45,586 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] metadata.Hive: Total time spent in each
metastore function (ms): {isCompatibleWith_(Configuration)=0,
getNotNullConstraints_(NotNullConstraintsRequest)=6,
getAllTableConstraints_(AllTableConstraintsRequest)=41, getMetaConf_(String)=1,
unlock_(long)=9, getTable_(GetTableRequest)=122, flushCache_()=1,
getCheckConstraints_(CheckConstraintsRequest)=5}
2025-03-27T12:50:45,586 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Driver: Completed compiling
command(queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4); Time
taken: 0.323 seconds
2025-03-27T12:50:45,587 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] common.LogUtils: Unregistered logging
context.
2025-03-27T12:50:45,588 INFO [HiveServer2-Background-Pool: Thread-204]
common.LogUtils: Thread context registration is done.
2025-03-27T12:50:45,588 INFO [HiveServer2-Background-Pool: Thread-204]
reexec.ReExecDriver: Execution #1 of query
2025-03-27T12:50:45,588 INFO [HiveServer2-Background-Pool: Thread-204]
lockmgr.DbTxnManager: Setting lock request transaction to txnid:0 for
queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:50:45,590 INFO [HiveServer2-Background-Pool: Thread-204]
lockmgr.DbLockManager: Requesting lock for
queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:50:45,610 INFO [HiveServer2-Background-Pool: Thread-204]
lockmgr.DbLockManager: Response to
queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
LockResponse(lockid:110, state:ACQUIRED)
2025-03-27T12:50:45,611 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Operation QUERY obtained 1 locks
2025-03-27T12:50:45,654 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Executing
command(queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4):
insert into ice_t values (1)
Query ID = hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:50:45,655 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Query ID = hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
Total jobs = 3
2025-03-27T12:50:45,655 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Total jobs = 3
Launching Job 1 out of 3
2025-03-27T12:50:45,655 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Launching Job 1 out of 3
2025-03-27T12:50:45,655 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-1:MAPRED] in serial mode
2025-03-27T12:50:45,670 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Context: New scratch dir is
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-4
2025-03-27T12:50:45,674 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezSessionPoolManager: The current user: hadoop-admin, session user:
hadoop-admin
2025-03-27T12:50:45,674 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezSessionPoolManager: Current queue name is null incoming queue name is
null
2025-03-27T12:50:45,674 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezTask: Subscribed to counters: [] for queryId:
hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:50:45,674 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezTask: Session is already open
2025-03-27T12:50:45,676 INFO [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: Resource modification time: 1743047059899 for
hdfs://owen/tmp/hive/hadoop-admin/_tez_session_dir/5a60c46d-8880-43d1-891b-3f35a20253f9-resources/hive-hooks-0.1.0.jar
2025-03-27T12:50:45,678 INFO [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: Resource modification time: 1743047060009 for
hdfs://owen/tmp/hive/hadoop-admin/_tez_session_dir/5a60c46d-8880-43d1-891b-3f35a20253f9-resources/json-serde-1.3.8-jar-with-dependencies.jar
2025-03-27T12:50:45,680 INFO [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: Resource modification time: 1743047059899 for
hdfs://owen/tmp/hive/hadoop-admin/_tez_session_dir/5a60c46d-8880-43d1-891b-3f35a20253f9-resources/hive-hooks-0.1.0.jar
2025-03-27T12:50:45,682 INFO [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: Resource modification time: 1743047060009 for
hdfs://owen/tmp/hive/hadoop-admin/_tez_session_dir/5a60c46d-8880-43d1-891b-3f35a20253f9-resources/json-serde-1.3.8-jar-with-dependencies.jar
2025-03-27T12:50:45,682 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezTask: Dag name: insert into ice_t values (1) (Stage-1)
2025-03-27T12:50:45,684 WARN [HiveServer2-Background-Pool: Thread-204]
tez.TezConfigurationFactory: Skip adding 'tez.application.tags' to dagConf, as
it's an AM scoped property
2025-03-27T12:50:45,686 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Context: New scratch dir is
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-4
2025-03-27T12:50:45,689 INFO [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: Vertex has custom input? false
2025-03-27T12:50:45,690 INFO [HiveServer2-Background-Pool: Thread-204]
exec.SerializationUtilities: Serializing MapWork using kryo
2025-03-27T12:50:45,693 INFO [HiveServer2-Background-Pool: Thread-204]
exec.Utilities: Serialized plan (via RPC) - name: Map 1 size: 6.18KB
2025-03-27T12:50:45,708 WARN [HiveServer2-Background-Pool: Thread-204]
tez.DagUtils: No Tez VCore size specified by hive.tez.cpu.vcores. Falling back
to MapReduce container VCores mapreduce.map.cpu.vcores
2025-03-27T12:50:45,711 INFO [HiveServer2-Background-Pool: Thread-204]
fs.FSStatsPublisher: created :
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1/-ext-10000
2025-03-27T12:50:45,712 INFO [HiveServer2-Background-Pool: Thread-204]
client.TezClient: Submitting dag to TezSession,
sessionName=HIVE-5a60c46d-8880-43d1-891b-3f35a20253f9,
applicationId=application_1741077053365_0130, dagName=insert into ice_t values
(1) (Stage-1), callerContext={ context=HIVE, callerType=HIVE_QUERY_ID,
callerId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4_User:hadoop-admin
}
2025-03-27T12:50:45,775 INFO [HiveServer2-Background-Pool: Thread-204]
client.FrameworkClient: Submitted dag to TezSession,
sessionName=HIVE-5a60c46d-8880-43d1-891b-3f35a20253f9,
applicationId=application_1741077053365_0130, dagId=dag_1741077053365_0130_2,
dagName=insert into ice_t values (1) (Stage-1)
2025-03-27T12:50:45,775 INFO [HiveServer2-Background-Pool: Thread-204]
tez.TezTask: HS2 Host: [owen-rm3], Query ID:
[hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4], Dag ID:
[dag_1741077053365_0130_2], DAG App ID: [application_1741077053365_0130]
Status: Running (Executing on YARN cluster with App id
application_1741077053365_0130)
2025-03-27T12:50:45,799 INFO [HiveServer2-Background-Pool: Thread-204]
SessionState: Status: Running (Executing on YARN cluster with App id
application_1741077053365_0130)
2025-03-27T12:50:45,806 INFO [HiveServer2-Background-Pool: Thread-204]
monitoring.RenderStrategy$LogToFileFunction: Map 1: -/-
2025-03-27T12:50:46,311 INFO [HiveServer2-Background-Pool: Thread-204]
monitoring.RenderStrategy$LogToFileFunction: Map 1: 0/1
2025-03-27T12:50:53,373 INFO [HiveServer2-Background-Pool: Thread-204]
monitoring.RenderStrategy$LogToFileFunction: Map 1: 0(+1)/1
2025-03-27T12:50:57,334 INFO [HiveServer2-Background-Pool: Thread-204]
monitoring.RenderStrategy$LogToFileFunction: Map 1: 1/1
2025-03-27T12:50:57,349 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-8:CONDITIONAL] in parallel
2025-03-27T12:50:57,351 INFO [Thread-97] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:57,351 INFO [Thread-97] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:57,367 INFO [Thread-97] hive.HiveIcebergOutputCommitter:
Cleaning job for jobID: job_17410770533650_0130, table:
org.apache.iceberg.mr.hive.HiveIcebergOutputCommitter$OutputTable@fa4579f2
2025-03-27T12:50:57,386 INFO [Thread-97] hive.HiveIcebergOutputCommitter:
Cleaning job for jobID: job_17410770533650_0130, table:
org.apache.iceberg.mr.hive.HiveIcebergOutputCommitter$OutputTable@fa4579f2
Stage-5 is selected by condition resolver.
2025-03-27T12:50:57,415 INFO [Thread-97] exec.Task: Stage-5 is selected by
condition resolver.
Stage-4 is filtered out by condition resolver.
2025-03-27T12:50:57,415 INFO [Thread-97] exec.Task: Stage-4 is filtered out by
condition resolver.
Stage-6 is filtered out by condition resolver.
2025-03-27T12:50:57,415 INFO [Thread-97] exec.Task: Stage-6 is filtered out by
condition resolver.
2025-03-27T12:50:57,415 INFO [Thread-97] common.LogUtils: Unregistered logging
context.
2025-03-27T12:50:57,416 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-5:MOVE] in serial mode
Moving data to directory hdfs://owen/user/hive/warehouse/ice_t
2025-03-27T12:50:57,423 INFO [HiveServer2-Background-Pool: Thread-204]
exec.Task: Moving data to directory hdfs://owen/user/hive/warehouse/ice_t from
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1/-ext-10001
Time taken to move files: 2 ms
2025-03-27T12:50:57,425 INFO [HiveServer2-Background-Pool: Thread-204]
exec.Task: Time taken to move files: 2 ms
2025-03-27T12:50:57,425 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-2:DEPENDENCY_COLLECTION] in parallel
2025-03-27T12:50:57,426 INFO [Thread-100] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:57,426 INFO [Thread-100] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:57,427 INFO [Thread-100] common.LogUtils: Unregistered
logging context.
2025-03-27T12:50:57,427 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-0:MOVE] in serial mode
2025-03-27T12:50:57,430 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Committing job(s) job_17410770533650_0130 has
started
2025-03-27T12:50:57,488 INFO [HiveServer2-Background-Pool: Thread-204]
iceberg.BaseMetastoreTableOperations: Refreshing table metadata from new
version:
hdfs://owen/user/hive/warehouse/ice_t/metadata/00000-8073025d-2cd5-42f4-82d7-ad9b983e85ac.metadata.json
2025-03-27T12:50:57,496 INFO [HiveServer2-Background-Pool: Thread-204]
iceberg.BaseMetastoreCatalog: Table loaded by catalog:
default_iceberg.default.ice_t
2025-03-27T12:50:57,496 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Committing job has started for table:
default_iceberg.default.ice_t, using location:
hdfs://owen/user/hive/warehouse/ice_t/temp/hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4-job_17410770533650_0130
[699.734s][info][gc] GC(45) Pause Young (Normal) (G1 Evacuation Pause)
220M->157M(256M) 34.614ms
2025-03-27T12:50:57,901 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveTableOperations: Committed to table default_iceberg.default.ice_t with
the new metadata location
hdfs://owen/user/hive/warehouse/ice_t/metadata/00001-eec2c770-4b07-40a8-a17c-560107629cf7.metadata.json
2025-03-27T12:50:57,901 INFO [HiveServer2-Background-Pool: Thread-204]
iceberg.BaseMetastoreTableOperations: Successfully committed to table
default_iceberg.default.ice_t in 219 ms
2025-03-27T12:50:57,901 INFO [HiveServer2-Background-Pool: Thread-204]
iceberg.SnapshotProducer: Committed snapshot 4417310429356719238 (MergeAppend)
2025-03-27T12:50:57,969 INFO [HiveServer2-Background-Pool: Thread-204]
iceberg.BaseMetastoreTableOperations: Refreshing table metadata from new
version:
hdfs://owen/user/hive/warehouse/ice_t/metadata/00001-eec2c770-4b07-40a8-a17c-560107629cf7.metadata.json
2025-03-27T12:50:58,021 INFO [HiveServer2-Background-Pool: Thread-204]
metrics.LoggingMetricsReporter: Received metrics report:
CommitReport{tableName=default_iceberg.default.ice_t,
snapshotId=4417310429356719238, sequenceNumber=1, operation=append,
commitMetrics=CommitMetricsResult{totalDuration=TimerResult{timeUnit=NANOSECONDS,
totalDuration=PT0.474986241S, count=1}, attempts=CounterResult{unit=COUNT,
value=1}, addedDataFiles=CounterResult{unit=COUNT, value=1},
removedDataFiles=null, totalDataFiles=CounterResult{unit=COUNT, value=1},
addedDeleteFiles=null, addedEqualityDeleteFiles=null,
addedPositionalDeleteFiles=null, removedDeleteFiles=null,
removedEqualityDeleteFiles=null, removedPositionalDeleteFiles=null,
totalDeleteFiles=CounterResult{unit=COUNT, value=0},
addedRecords=CounterResult{unit=COUNT, value=1}, removedRecords=null,
totalRecords=CounterResult{unit=COUNT, value=1},
addedFilesSizeInBytes=CounterResult{unit=BYTES, value=414},
removedFilesSizeInBytes=null, totalFilesSizeInBytes=CounterResult{unit=BYTES,
value=414}, addedPositionalDeletes=null, removedPositionalDeletes=null,
totalPositionalDeletes=CounterResult{unit=COUNT, value=0},
addedEqualityDeletes=null, removedEqualityDeletes=null,
totalEqualityDeletes=CounterResult{unit=COUNT, value=0}},
metadata={iceberg-version=Apache Iceberg 1.6.1 (commit
8e9d59d299be42b0bca9461457cd1e95dbaad086)}}
2025-03-27T12:50:58,022 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Write commit took 515 ms for table:
default_iceberg.default.ice_t with 1 data and 0 delete file(s)
2025-03-27T12:50:58,022 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Commit took 592 ms for job(s)
job_17410770533650_0130
2025-03-27T12:50:58,022 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Cleaning for job job_17410770533650_0130
started
2025-03-27T12:50:58,022 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Cleaning location:
hdfs://owen/user/hive/warehouse/ice_t/temp/hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4-job_17410770533650_0130
2025-03-27T12:50:58,026 INFO [HiveServer2-Background-Pool: Thread-204]
hive.HiveIcebergOutputCommitter: Cleaning for job job_17410770533650_0130
finished
2025-03-27T12:50:58,026 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Starting task [Stage-3:STATS] in parallel
2025-03-27T12:50:58,027 INFO [Thread-108] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:58,027 INFO [Thread-108] common.LogUtils: Thread context
registration is done.
2025-03-27T12:50:58,029 INFO [Thread-108] metastore.HiveMetaStoreClient: HMS
client filtering is enabled.
2025-03-27T12:50:58,030 INFO [Thread-108] metastore.HiveMetaStoreClient:
Resolved metastore uris: [...]
2025-03-27T12:50:58,030 INFO [Thread-108] metastore.HiveMetaStoreClient:
Trying to connect to metastore with URI (...) in binary transport mode
2025-03-27T12:50:58,035 INFO [Thread-108] metastore.HiveMetaStoreClient:
Opened a connection to metastore, URI (...) current connections: 9
2025-03-27T12:50:58,035 INFO [Thread-108] metastore.RetryingMetaStoreClient:
RetryingMetaStoreClient proxy=class
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ...
2025-03-27T12:50:58,107 INFO [Thread-108] stats.BasicStatsTask: Executing
stats task
2025-03-27T12:50:58,109 INFO [Thread-108] fs.FSStatsPublisher: created :
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1/-ext-10000
2025-03-27T12:50:58,199 INFO [Thread-108]
iceberg.BaseMetastoreTableOperations: Refreshing table metadata from new
version:
hdfs://owen/user/hive/warehouse/ice_t/metadata/00001-eec2c770-4b07-40a8-a17c-560107629cf7.metadata.json
2025-03-27T12:50:58,204 INFO [Thread-108] iceberg.BaseMetastoreCatalog: Table
loaded by catalog: default_iceberg.default.ice_t
2025-03-27T12:50:58,252 INFO [Thread-108]
iceberg.BaseMetastoreTableOperations: Refreshing table metadata from new
version:
hdfs://owen/user/hive/warehouse/ice_t/metadata/00001-eec2c770-4b07-40a8-a17c-560107629cf7.metadata.json
2025-03-27T12:50:58,257 INFO [Thread-108] iceberg.BaseMetastoreCatalog: Table
loaded by catalog: default_iceberg.default.ice_t
2025-03-27T12:50:58,258 INFO [Thread-108] hive.HiveIcebergSerDe: Using schema
from existing table
{"type":"struct","schema-id":0,"fields":[{"id":1,"name":"i","required":false,"type":"int"}]}
2025-03-27T12:50:58,258 WARN [Thread-108] metadata.Hive: Cannot get a table
snapshot for ice_t
2025-03-27T12:50:58,300 WARN [Thread-108] util.Tasks: Retrying task after
failure: Waiting for lock on table default.ice_t
org.apache.iceberg.hive.MetastoreLock$WaitingForLockException: Waiting for lock
on table default.ice_t
at
org.apache.iceberg.hive.MetastoreLock.lambda$acquireLock$1(MetastoreLock.java:216)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:413)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:219)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:203)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.hive.MetastoreLock.acquireLock(MetastoreLock.java:210)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.iceberg.hive.MetastoreLock.lock(MetastoreLock.java:142)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:418)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:?]
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:?]
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:?]
at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at com.sun.proxy.$Proxy39.alter_table(Unknown Source) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:?]
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:?]
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:?]
at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at com.sun.proxy.$Proxy39.alter_table(Unknown Source) ~[?:?]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
...
...
...
2025-03-27T12:53:55,131 WARN [Thread-108] util.Tasks: Retrying task after
failure: Waiting for lock on table default.ice_t
org.apache.iceberg.hive.MetastoreLock$WaitingForLockException: Waiting for lock
on table default.ice_t
at
org.apache.iceberg.hive.MetastoreLock.lambda$acquireLock$1(MetastoreLock.java:216)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.util.Tasks$Builder.runTaskWithRetry(Tasks.java:413)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.util.Tasks$Builder.runSingleThreaded(Tasks.java:219)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.iceberg.util.Tasks$Builder.run(Tasks.java:203)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.hive.MetastoreLock.acquireLock(MetastoreLock.java:210)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.iceberg.hive.MetastoreLock.lock(MetastoreLock.java:142)
~[hive-iceberg-catalog-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:418)
~[hive-iceberg-handler-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:?]
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:?]
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:?]
at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at com.sun.proxy.$Proxy39.alter_table(Unknown Source) ~[?:?]
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
~[?:?]
at
jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
~[?:?]
at
jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[?:?]
at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at com.sun.proxy.$Proxy39.alter_table(Unknown Source) ~[?:?]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
~[hive-exec-4.1.0-SNAPSHOT.jar:4.1.0-SNAPSHOT]
2025-03-27T12:54:00,294 INFO [Thread-108] util.Tasks: Stopping retries after
182004 ms
2025-03-27T12:54:00,303 INFO [Thread-108] hive.MetastoreLock: No lock found
with Iceberg-df6861e6-8e49-4cac-a2a8-2d0362a8d535 agentInfo
[Warning] could not update stats.
2025-03-27T12:54:00,304 INFO [Thread-108] stats.BasicStatsTask: [Warning]
could not update stats.Failed with exception Unable to alter table.
org.apache.iceberg.hive.LockException: Timed out after 182005 ms waiting for
lock on default.ice_t
at
org.apache.iceberg.hive.MetastoreLock.acquireLock(MetastoreLock.java:245)
at org.apache.iceberg.hive.MetastoreLock.lock(MetastoreLock.java:142)
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:418)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
org.apache.hadoop.hive.ql.metadata.HiveException: Unable to alter table.
org.apache.iceberg.hive.LockException: Timed out after 182005 ms waiting for
lock on default.ice_t
at
org.apache.iceberg.hive.MetastoreLock.acquireLock(MetastoreLock.java:245)
at org.apache.iceberg.hive.MetastoreLock.lock(MetastoreLock.java:142)
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:418)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:940)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
Caused by: MetaException(message:org.apache.iceberg.hive.LockException: Timed
out after 182005 ms waiting for lock on default.ice_t
at
org.apache.iceberg.hive.MetastoreLock.acquireLock(MetastoreLock.java:245)
at org.apache.iceberg.hive.MetastoreLock.lock(MetastoreLock.java:142)
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:418)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:882)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:862)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.aggregateStats(BasicStatsTask.java:306)
at
org.apache.hadoop.hive.ql.stats.BasicStatsTask.process(BasicStatsTask.java:106)
at org.apache.hadoop.hive.ql.exec.StatsTask.execute(StatsTask.java:111)
at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:214)
at
org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:105)
at org.apache.hadoop.hive.ql.exec.TaskRunner.run(TaskRunner.java:83)
)
at
org.apache.iceberg.mr.hive.HiveIcebergMetaHook.preAlterTable(HiveIcebergMetaHook.java:422)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient.alter_table(HiveMetaStoreClient.java:571)
at
org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient.alter_table(SessionHiveMetaStoreClient.java:509)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:213)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at
java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at
org.apache.hadoop.hive.metastore.HiveMetaStoreClient$SynchronizedHandler.invoke(HiveMetaStoreClient.java:4652)
at com.sun.proxy.$Proxy39.alter_table(Unknown Source)
at org.apache.hadoop.hive.ql.metadata.Hive.alterTable(Hive.java:936)
... 8 more
StatsTask took 182313
2025-03-27T12:54:00,340 INFO [Thread-108] exec.Task: StatsTask took 182313
2025-03-27T12:54:00,341 INFO [Thread-108] metastore.HiveMetaStoreClient:
Closed a connection to metastore, current connections: 9
2025-03-27T12:54:00,341 INFO [Thread-108] common.LogUtils: Unregistered
logging context.
2025-03-27T12:54:00,342 INFO [HiveServer2-Background-Pool: Thread-204]
metadata.Hive: Dumping metastore api call timing information for : execution
phase
2025-03-27T12:54:00,342 INFO [HiveServer2-Background-Pool: Thread-204]
metadata.Hive: Total time spent in each metastore function (ms):
{isCompatibleWith_(Configuration)=0}
2025-03-27T12:54:00,342 INFO [HiveServer2-Background-Pool: Thread-204]
ql.Driver: Completed executing
command(queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4); Time
taken: 194.688 seconds
2025-03-27T12:54:00,342 INFO [HiveServer2-Background-Pool: Thread-204]
lockmgr.DbTxnManager: Stopped heartbeat for query:
hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
2025-03-27T12:54:00,343 INFO [HiveServer2-Background-Pool: Thread-204]
lockmgr.DbLockManager: releaseLocks: [lockid:110
queryId=hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4 txnid:0]
2025-03-27T12:54:00,351 INFO [HiveServer2-Background-Pool: Thread-204]
reexec.ReExecDriver: Re-execution decision is made according to:
executionIndex: 1, maxExecutions: 2, shouldReExecute: false
2025-03-27T12:54:00,352 INFO [HiveServer2-Background-Pool: Thread-204]
common.LogUtils: Unregistered logging context.
2025-03-27T12:54:00,412 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.OperationManager: Closing
operation: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=fd31c8f8-662b-44c0-9971-8d9998098703]
2025-03-27T12:54:00,412 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.OperationManager: Removed
queryId: hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4 corresponding
to operation: OperationHandle [opType=EXECUTE_STATEMENT,
getHandleIdentifier()=fd31c8f8-662b-44c0-9971-8d9998098703] with tag: null
2025-03-27T12:54:00,412 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Context: Deleting scratch dir:
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:54:00,412 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] cleanup.EventualCleanupService: Delete
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-1
operation was queued
2025-03-27T12:54:00,413 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Context: Deleting scratch dir:
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:54:00,413 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] cleanup.EventualCleanupService: Delete
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1
operation was queued
2025-03-27T12:54:00,413 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] ql.Context: Deleting scratch dir:
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-4
2025-03-27T12:54:00,414 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] cleanup.EventualCleanupService: Delete
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-4
operation was queued
2025-03-27T12:54:00,414 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.SQLOperation: Closing operation
log
/opt/.../log/hive/operation_logs/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
without delay
2025-03-27T12:54:00,416 INFO [59fba971-a3aa-4d11-87e9-c2d3b96a491c
HiveServer2-Handler-Pool: Thread-85] operation.OperationLogManager: The
operation log location changes from
/opt/.../log/hive/operation_logs/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4
to
/opt/.../log/hive/operation_logs_historic/owen-rm3_10000_1743046764870/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_20250327125045_22d5e40b-e2c5-49c8-a731-3acf6750edc4.
2025-03-27T12:54:00,416 INFO [EventualCleanupService thread 5]
cleanup.EventualCleanupService: Deleted
hdfs://owen/user/hive/warehouse/ice_t/.hive-staging_hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:54:00,417 INFO [EventualCleanupService thread 4]
cleanup.EventualCleanupService: Deleted
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-1
2025-03-27T12:54:00,417 INFO [EventualCleanupService thread 6]
cleanup.EventualCleanupService: Deleted
hdfs://owen/tmp/hive/hadoop-admin/59fba971-a3aa-4d11-87e9-c2d3b96a491c/hive_2025-03-27_12-50-45_262_86943509849808998-4
