Nachiket Vaidya created HIVE-13869:
--------------------------------------
Summary: ObjectStore synchronization issue manifested in db
notification listener
Key: HIVE-13869
URL: https://issues.apache.org/jira/browse/HIVE-13869
Project: Hive
Issue Type: Bug
Components: HCatalog
Affects Versions: 1.1.1
Reporter: Nachiket Vaidya
Fix For: 1.2.2
I used pyhs2 python client to create tables/partitions in hive. I was working
fine until I moved to multithreaded scripts which created 8 connections and ran
DDL queries concurrently.
I got the error as
{noformat}
2016-05-04 17:49:26,226 ERROR
org.apache.hadoop.hive.metastore.RetryingHMSHandler: [pool-4-thread-194]:
HMSHandler Fatal error: Invalid state. Transaction has already started
org.datanucleus.transaction.NucleusTransactionException: Invalid state.
Transaction has already started
at
org.datanucleus.transaction.TransactionManager.begin(TransactionManager.java:47)
at org.datanucleus.TransactionImpl.begin(TransactionImpl.java:131)
at
org.datanucleus.api.jdo.JDOTransaction.internalBegin(JDOTransaction.java:88)
at org.datanucleus.api.jdo.JDOTransaction.begin(JDOTransaction.java:80)
at
org.apache.hadoop.hive.metastore.ObjectStore.openTransaction(ObjectStore.java:463)
at
org.apache.hadoop.hive.metastore.ObjectStore.addNotificationEvent(ObjectStore.java:7522)
at sun.reflect.GeneratedMethodAccessor20.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
at com.sun.proxy.$Proxy10.addNotificationEvent(Unknown Source)
at
org.apache.hive.hcatalog.listener.DbNotificationListener.enqueue(DbNotificationListener.java:261)
at
org.apache.hive.hcatalog.listener.DbNotificationListener.onCreateTable(DbNotificationListener.java:123)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1483)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1502)
at sun.reflect.GeneratedMethodAccessor57.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
at com.sun.proxy.$Proxy14.create_table_with_environment_context(Unknown
Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$create_table_with_environment_context.getResult(ThriftHiveMetastore.java:9267)
{noformat}
At one point, I got another stack trace as
{noformat}
2016-05-26 12:32:27,904 ERROR
org.apache.hadoop.hive.metastore.RetryingHMSHandler: [pool-4-thread-7]:
MetaException(message:java.lang.NullPointerException)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.newMetaException(HiveMetaStore.java:5535)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.add_partitions_req(HiveMetaStore.java:2308)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invokeInternal(RetryingHMSHandler.java:138)
at
org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:99)
at com.sun.proxy.$Proxy14.add_partitions_req(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$add_partitions_req.getResult(ThriftHiveMetastore.java:9723)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$add_partitions_req.getResult(ThriftHiveMetastore.java:9707)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at
org.apache.hadoop.hive.metastore.TUGIBasedProcessor$1.run(TUGIBasedProcessor.java:110)
at
org.apache.hadoop.hive.metastore.TUGIBasedProcessor$1.run(TUGIBasedProcessor.java:106)
at java.security.AccessController.doPrivileged(Native Method)
at javax.security.auth.Subject.doAs(Subject.java:415)
at
org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1693)
at
org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.NullPointerException
at
com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1245)
at
com.jolbox.bonecp.StatementHandle.executeBatch(StatementHandle.java:424)
at
org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeBatch(ParamLoggingPreparedStatement.java:372)
at
org.datanucleus.store.rdbms.SQLController.processConnectionStatement(SQLController.java:628)
at
org.datanucleus.store.rdbms.SQLController.getStatementForQuery(SQLController.java:324)
at
org.datanucleus.store.rdbms.query.RDBMSQueryUtils.getPreparedStatementForQuery(RDBMSQueryUtils.java:194)
at
org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:640)
at org.datanucleus.store.query.Query.executeQuery(Query.java:1786)
at org.datanucleus.store.query.Query.executeWithArray(Query.java:1672)
at org.datanucleus.store.query.Query.execute(Query.java:1654)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:221)
at
org.apache.hadoop.hive.metastore.ObjectStore.addNotificationEvent(ObjectStore.java:7534)
at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at
org.apache.hadoop.hive.metastore.RawStoreProxy.invoke(RawStoreProxy.java:114)
at com.sun.proxy.$Proxy10.addNotificationEvent(Unknown Source)
at
org.apache.hive.hcatalog.listener.DbNotificationListener.enqueue(DbNotificationListener.java:261)
at
org.apache.hive.hcatalog.listener.DbNotificationListener.onAddPartition(DbNotificationListener.java:168)
{noformat}
It is concurrency issue manifesting in different way.
We need to revisit ObjectStore and db notification listener's use of
ObjectStore to understand the issue.
The patch for HIVE-13836 avoids concurrent calls to ObjectStore. But we need to
find the root cause of the real issue as ObjectStore should handle concurrent
calls.
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
