Bala Krishna created HIVE-7290:
----------------------------------
Summary: BoneCP Connection Pooling throwing JDODataStoreException
with Hive 0.13.1
Key: HIVE-7290
URL: https://issues.apache.org/jira/browse/HIVE-7290
Project: Hive
Issue Type: Bug
Components: Database/Schema, Metastore
Affects Versions: 0.13.1
Environment: Hadoop 2.2.0
Hive 0.13.1
BoneCP 0.8.0.RELEASE
Reporter: Bala Krishna
Hi folks,
we're seeing an intermittent issue between our Hive 0.13 metastore and mysql
instance. After being idle for about 5 minutes or so, any transactions
involving the metastore and mysql causes the following error to appear in the
metastore log:
2014-06-09 05:13:52,066 ERROR bonecp.ConnectionHandle
(ConnectionHandle.java:markPossiblyBroken(388)) - Database access problem.
Killing off this connection and all remaining connectio
ns in the connection pool. SQL State = 08S01
2014-06-09 05:13:52,068 ERROR metastore.RetryingHMSHandler
(RetryingHMSHandler.java:invoke(157)) - Retrying HMSHandler after 1000 ms
(attempt 1 of 1) with error: javax.jdo.JDODataStore
Exception: Communications link failure
The last packet successfully received from the server was 502,751 milliseconds
ago. The last packet sent successfully to the server was 1 milliseconds ago.
at
org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:451)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:275)
at
org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:900)
at
org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:832)
at sun.reflect.GeneratedMethodAccessor9.invoke(Unknown Source)
[full stack trace is below]
Subsequent transactions go through fine, however. This only occurs if the
metastore has has been idle for a while.
We've been looking at the code and the problem seems to lie in the channel
between the driver and metastore connection pool. We looked at the wait time
configuration settings both mysql and BoneCP. Both of them are set for max
value.
Our hive 0.12 install uses DBCP for datanucleus.connectionPoolingType, not
BoneCP and we don't see these issues there. We are not running Tez.
This seems like such a basic issue that we'd thought to check and see if anyone
else has encountered it. Any insights would be greatly appreciated.
=================
Full stack trace:
2014-06-09 05:13:52,066 ERROR bonecp.ConnectionHandle
(ConnectionHandle.java:markPossiblyBroken(388)) - Database access problem.
Killing off this connection and all remaining connectio
ns in the connection pool. SQL State = 08S01
2014-06-09 05:13:52,068 ERROR metastore.RetryingHMSHandler
(RetryingHMSHandler.java:invoke(157)) - Retrying HMSHandler after 1000 ms
(attempt 1 of 1) with error: javax.jdo.JDODataStore
Exception: Communications link failure
The last packet successfully received from the server was 502,751 milliseconds
ago. The last packet sent successfully to the server was 1 milliseconds ago.
at
org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:451)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:275)
at
org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:900)
at
org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:832)
at sun.reflect.GeneratedMethodAccessor9.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:108)
at com.sun.proxy.$Proxy0.getTable(Unknown Source)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_table(HiveMetaStore.java:1559)
at sun.reflect.GeneratedMethodAccessor15.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.invoke(RetryingHMSHandler.java:105)
at com.sun.proxy.$Proxy11.get_table(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:8146)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:8130)
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:107)
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:1491)
at
org.apache.hadoop.hive.shims.HadoopShimsSecure.doAs(HadoopShimsSecure.java:500)
at
org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:206)
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:744)
NestedThrowablesStackTrace:
com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link
failure
The last packet successfully received from the server was 502,751 milliseconds
ago. The last packet sent successfully to the server was 1 milliseconds ago.
at sun.reflect.GeneratedConstructorAccessor41.newInstance(Unknown
Source)
at
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:526)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:411)
at
com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1117)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3603)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3492)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4043)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2503)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2664)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2788)
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:5282)
at
com.jolbox.bonecp.ConnectionHandle.setAutoCommit(ConnectionHandle.java:1292)
at
org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:440)
at
org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getXAResource(ConnectionFactoryImpl.java:378)
at
org.datanucleus.store.connection.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:328)
at
org.datanucleus.store.connection.AbstractConnectionFactory.getConnection(AbstractConnectionFactory.java:94)
at
org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:430)
at
org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:396)
at
org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:621)
at org.datanucleus.store.query.Query.executeQuery(Query.java:1786)
at org.datanucleus.store.query.Query.executeWithArray(Query.java:1672)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:266)
at
org.apache.hadoop.hive.metastore.ObjectStore.getMTable(ObjectStore.java:900)
at
org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:832)
at sun.reflect.GeneratedMethodAccessor9.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:108)
at com.sun.proxy.$Proxy0.getTable(Unknown Source)
at
org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_table(HiveMetaStore.java:1559)
at sun.reflect.GeneratedMethodAccessor15.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.invoke(RetryingHMSHandler.java:105)
at com.sun.proxy.$Proxy11.get_table(Unknown Source)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:8146)
at
org.apache.hadoop.hive.metastore.api.ThriftHiveMetastore$Processor$get_table.getResult(ThriftHiveMetastore.java:8130)
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:107)
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:1491)
at
org.apache.hadoop.hive.shims.HadoopShimsSecure.doAs(HadoopShimsSecure.java:500)
at
org.apache.hadoop.hive.metastore.TUGIBasedProcessor.process(TUGIBasedProcessor.java:118)
at
org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:206)
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:744)
Caused by: java.io.EOFException: Can not read response from server. Expected to
read 4 bytes, read 0 bytes before connection was unexpectedly lost.
at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:3052)
at com.mysql.jdbc.MysqlIO.reuseAndReadPacket(MysqlIO.java:3503)
... 44 more
--
This message was sent by Atlassian JIRA
(v6.2#6252)
