Thanks for the response and suggestion Rick. That certainly seems like a plausible solution given that we are using the mysql server as a metastore for more than a few dev and prod hive instances. I think also with hive v0.12 the connection pooling middleware is different (BoneCP) so who knows what that brought into the mix. And... given the randomness of the error it sure smells like a runtime-y kinda thing.
so far it looks like its working! thanks, stephen. On Tue, Dec 17, 2013 at 6:10 PM, Richard Nadeau <strout...@gmail.com> wrote: > 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) >> >>
