Hi Stephen, Try increasing the max connections limit in MySQL. I ran into a similar problem and this resolved things after a Hive 0.12 upgrade. You can increase the connection limit without a restart, but pay attention to other settings as well so that you don't over allocate resources on your db server.
Regards, Rick On Dec 17, 2013 6:12 PM, "Stephen Sprague" <sprag...@gmail.com> wrote: > hi guys, > I'm pretty much at my wits end on this one. i'm using hive v0.12 against a > mysql metastore. the error manifests itself (mostly randomly which is the > problem) as this error in the client: > > 2013-12-17 16:54:03,158 ERROR metastore.RetryingRawStore > (RetryingRawStore.java:invoke(146)) - JDO datastore error. Retrying > metastore command after 1000 ms (attempt 1 of 1) > 2013-12-17 16:54:04,345 ERROR metastore.RetryingHMSHandler > (RetryingHMSHandler.java:invoke(141)) - > MetaException(message:java.lang.RuntimeException: commitTransaction was > called but openTransactionCalls = 0. This probably indicates that there are > unbalanced calls to openTransaction/commitTransaction) > > > but i believe this to be just a symptom of something happening further > upstream. > > > examining the hive.log file for this useer (under /tmp/<user>/hive.log) i > find this hideous traceback with "bonecp" being the focus of attention. > There's nothing wrong with the mysql server metastore especially given it > works sometimes. to me i think it has something to do with the connection > pooling logic but that's only speculation. > > before i surrender and rollback to a previous version i ask: Has anyone > encountered this before? Or are there any nuggets in the traceback worthy > of insight? > > thanks, > Stephen. > > > 2013-12-17 16:54:03,142 ERROR bonecp.ConnectionHandle > (ConnectionHandle.java:markPossiblyBroken(297)) - Database access problem. > Killing off all remaining connections in the connection pool. SQL State = > 08S01 > 2013-12-17 16:54:03,144 ERROR bonecp.ConnectionHandle > (ConnectionHandle.java:markPossiblyBroken(297)) - Database access problem. > Killing off all remaining connections in the connection pool. SQL State = > 08007 > 2013-12-17 16:54:03,146 ERROR bonecp.ConnectionHandle > (ConnectionHandle.java:markPossiblyBroken(297)) - Database access problem. > Killing off all remaining connections in the connection pool. SQL State = > 08007 > 2013-12-17 16:54:03,147 ERROR bonecp.ConnectionHandle > (ConnectionHandle.java:markPossiblyBroken(297)) - Database access problem. > Killing off all remaining connections in the connection pool. SQL State = > 08007 > 2013-12-17 16:54:03,148 ERROR bonecp.BoneCP > (BoneCP.java:terminateAllConnections(199)) - Error in attempting to close > connection > com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: > Communications link failure during rollback(). Transaction resolution > unknown. > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native > Method) > at > sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) > at > sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) > at java.lang.reflect.Constructor.newInstance(Constructor.java:513) > at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) > at com.mysql.jdbc.Util.getInstance(Util.java:386) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927) > at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4730) > at > com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4325) > at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1557) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:396) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.getTransactionIsolation(ConnectionHandle.java:635) > at > org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:422) > at > org.datanucleus.store.rdbms.SQLController.getStatementForQuery(SQLController.java:316) > at > org.datanucleus.store.rdbms.SQLController.getStatementForQuery(SQLController.java:300) > at > org.datanucleus.store.rdbms.valuegenerator.SequenceTable.getNextVal(SequenceTable.java:194) > at > org.datanucleus.store.rdbms.valuegenerator.TableGenerator.reserveBlock(TableGenerator.java:190) > at > org.datanucleus.store.valuegenerator.AbstractGenerator.reserveBlock(AbstractGenerator.java:305) > at > org.datanucleus.store.rdbms.valuegenerator.AbstractRDBMSGenerator.obtainGenerationBlock(AbstractRDBMSGenerator.java:98) > at > org.datanucleus.store.valuegenerator.AbstractGenerator.obtainGenerationBlock(AbstractGenerator.java:197) > at > org.datanucleus.store.valuegenerator.AbstractGenerator.next(AbstractGenerator.java:105) > at > org.datanucleus.store.rdbms.RDBMSStoreManager.getStrategyValueForGenerator(RDBMSStoreManager.java:2019) > at > org.datanucleus.store.AbstractStoreManager.getStrategyValue(AbstractStoreManager.java:1385) > at > org.datanucleus.ExecutionContextImpl.newObjectId(ExecutionContextImpl.java:3727) > at > org.datanucleus.state.JDOStateManager.setIdentity(JDOStateManager.java:2574) > at > org.datanucleus.state.JDOStateManager.initialiseForPersistentNew(JDOStateManager.java:526) > at > org.datanucleus.state.ObjectProviderFactoryImpl.newForPersistentNew(ObjectProviderFactoryImpl.java:202) > at > org.datanucleus.ExecutionContextImpl.newObjectProviderForPersistentNew(ExecutionContextImpl.java:1326) > at > org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2123) > at > org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2212) > at > org.datanucleus.store.rdbms.mapping.java.PersistableMapping.setObjectAsValue(PersistableMapping.java:567) > at > org.datanucleus.store.rdbms.mapping.java.PersistableMapping.setObject(PersistableMapping.java:326) > at > org.datanucleus.store.rdbms.fieldmanager.ParameterSetter.storeObjectField(ParameterSetter.java:193) > at > org.datanucleus.state.JDOStateManager.providedObjectField(JDOStateManager.java:1272) > at > org.apache.hadoop.hive.metastore.model.MTable.jdoProvideField(MTable.java) > at > org.apache.hadoop.hive.metastore.model.MTable.jdoProvideFields(MTable.java) > at > org.datanucleus.state.JDOStateManager.provideFields(JDOStateManager.java:1349) > at > org.datanucleus.store.rdbms.request.InsertRequest.execute(InsertRequest.java:289) > at > org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertTable(RDBMSPersistenceHandler.java:167) > at > org.datanucleus.store.rdbms.RDBMSPersistenceHandler.insertObject(RDBMSPersistenceHandler.java:143) > at > org.datanucleus.state.JDOStateManager.internalMakePersistent(JDOStateManager.java:3777) > at > org.datanucleus.state.JDOStateManager.makePersistent(JDOStateManager.java:3753) > at > org.datanucleus.ExecutionContextImpl.persistObjectInternal(ExecutionContextImpl.java:2124) > at > org.datanucleus.ExecutionContextImpl.persistObjectWork(ExecutionContextImpl.java:1972) > at > org.datanucleus.ExecutionContextImpl.persistObject(ExecutionContextImpl.java:1820) > at > org.datanucleus.ExecutionContextThreadedImpl.persistObject(ExecutionContextThreadedImpl.java:217) > at > org.datanucleus.api.jdo.JDOPersistenceManager.jdoMakePersistent(JDOPersistenceManager.java:727) > at > org.datanucleus.api.jdo.JDOPersistenceManager.makePersistent(JDOPersistenceManager.java:752) > at > org.apache.hadoop.hive.metastore.ObjectStore.createTable(ObjectStore.java:648) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingRawStore.invoke(RetryingRawStore.java:124) > at $Proxy4.createTable(Unknown Source) > at > org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_core(HiveMetaStore.java:1074) > at > org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.create_table_with_environment_context(HiveMetaStore.java:1107) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:103) > at $Proxy9.create_table_with_environment_context(Unknown Source) > at > org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:482) > at > org.apache.hadoop.hive.metastore.HiveMetaStoreClient.createTable(HiveMetaStoreClient.java:471) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) > at $Proxy10.createTable(Unknown Source) > at > org.apache.hadoop.hive.ql.metadata.Hive.createTable(Hive.java:596) > at > org.apache.hadoop.hive.ql.exec.DDLTask.createTable(DDLTask.java:3661) > at org.apache.hadoop.hive.ql.exec.DDLTask.execute(DDLTask.java:252) > at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:151) > at > org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:65) > at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1414) > at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1192) > at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1020) > at org.apache.hadoop.hive.ql.Driver.run(Driver.java:888) > at > org.apache.hadoop.hive.service.HiveServer$HiveServerHandler.execute(HiveServer.java:198) > at > org.apache.hadoop.hive.service.ThriftHive$Processor$execute.getResult(ThriftHive.java:644) > at > org.apache.hadoop.hive.service.ThriftHive$Processor$execute.getResult(ThriftHive.java:628) > at > org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39) > at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39) > at > org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:206) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:662) > 2013-12-17 16:54:03,153 ERROR bonecp.BoneCP > (BoneCP.java:terminateAllConnections(199)) - Error in attempting to close > connection > com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: > Communications link failure during rollback(). Transaction resolution > unknown. > at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native > Method) > at > sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39) > at > sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27) > at java.lang.reflect.Constructor.newInstance(Constructor.java:513) > at com.mysql.jdbc.Util.handleNewInstance(Util.java:411) > at com.mysql.jdbc.Util.getInstance(Util.java:386) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1013) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:987) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:982) > at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:927) > at com.mysql.jdbc.ConnectionImpl.rollback(ConnectionImpl.java:4730) > at > com.mysql.jdbc.ConnectionImpl.realClose(ConnectionImpl.java:4325) > at com.mysql.jdbc.ConnectionImpl.close(ConnectionImpl.java:1557) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:396) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.internalClose(ConnectionHandle.java:404) > at > com.jolbox.bonecp.BoneCP.terminateAllConnections(BoneCP.java:197) > at > com.jolbox.bonecp.ConnectionHandle.markPossiblyBroken(ConnectionHandle.java:298) > at > com.jolbox.bonecp.ConnectionHandle.getTransactionIsolation(ConnectionHandle.java:635) > at > org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getConnection(ConnectionFactoryImpl.java:422) > at > org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.getXAResource(ConnectionFactoryImpl.java:356) > at > org.datanucleus.store.connection.ConnectionManagerImpl.allocateConnection(ConnectionManagerImpl.java:328) > at > org.datanucleus.store.connection.AbstractConnectionFactory.getConnection(AbstractConnectionFactory.java:64) > at > org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:429) > at > org.datanucleus.store.AbstractStoreManager.getConnection(AbstractStoreManager.java:395) > at > org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:607) > 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:826) > at > org.apache.hadoop.hive.metastore.ObjectStore.getTable(ObjectStore.java:760) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingRawStore.invoke(RetryingRawStore.java:124) > at $Proxy12.getTable(Unknown Source) > at > org.apache.hadoop.hive.metastore.HiveMetaStore$HMSHandler.get_table(HiveMetaStore.java:1371) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingHMSHandler.invoke(RetryingHMSHandler.java:103) > at $Proxy13.get_table(Unknown Source) > at > org.apache.hadoop.hive.metastore.HiveMetaStoreClient.getTable(HiveMetaStoreClient.java:854) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.apache.hadoop.hive.metastore.RetryingMetaStoreClient.invoke(RetryingMetaStoreClient.java:89) > at $Proxy14.getTable(Unknown Source) > at org.apache.hadoop.hive.ql.metadata.Hive.getTable(Hive.java:950) > at org.apache.hadoop.hive.ql.metadata.Hive.getTable(Hive.java:892) > at > org.apache.hadoop.hive.ql.exec.MoveTask.execute(MoveTask.java:245) > at org.apache.hadoop.hive.ql.exec.Task.executeTask(Task.java:151) > at > org.apache.hadoop.hive.ql.exec.TaskRunner.runSequential(TaskRunner.java:65) > at org.apache.hadoop.hive.ql.Driver.launchTask(Driver.java:1414) > at org.apache.hadoop.hive.ql.Driver.execute(Driver.java:1192) > at org.apache.hadoop.hive.ql.Driver.runInternal(Driver.java:1020) > at org.apache.hadoop.hive.ql.Driver.run(Driver.java:888) > at > org.apache.hadoop.hive.cli.CliDriver.processLocalCmd(CliDriver.java:259) > at > org.apache.hadoop.hive.cli.CliDriver.processCmd(CliDriver.java:216) > at > org.apache.hadoop.hive.cli.CliDriver.processLine(CliDriver.java:413) > at > org.apache.hadoop.hive.cli.CliDriver.executeDriver(CliDriver.java:781) > at org.apache.hadoop.hive.cli.CliDriver.run(CliDriver.java:675) > at org.apache.hadoop.hive.cli.CliDriver.main(CliDriver.java:614) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at org.apache.hadoop.util.RunJar.main(RunJar.java:208) > >
