[
https://issues.apache.org/jira/browse/HIVE-21550?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Laszlo Bodor updated HIVE-21550:
--------------------------------
Comment: was deleted
(was: [~pvary]: could you please review? unfortunately, I cannot be 100% that
this solves the problem (however, I couldn't reproduce the lock issue locally
since the change)
maybe we can reopen later if needed
)
> TestObjectStore tests are flaky - A lock could not be obtained within the
> time requested
> -----------------------------------------------------------------------------------------
>
> Key: HIVE-21550
> URL: https://issues.apache.org/jira/browse/HIVE-21550
> Project: Hive
> Issue Type: Bug
> Reporter: Laszlo Bodor
> Assignee: Laszlo Bodor
> Priority: Major
> Attachments: HIVE-21550.01.patch, HIVE-21550.repro.patch,
> TEST-230_UTBatch_standalone-metastore__metastore-server_20_tests-TEST-org.apache.hadoop.hive.metastore.TestObjectStore.xml,
> maven-test.txt, org.apache.hadoop.hive.metastore.TestObjectStore-output.txt,
> screenshot-builds.apache.org-2019.03.30-12-38-32.png,
> surefire_derby_stacktrace.log
>
>
> found in HIVE-21396
> TestObjectStore contains 24 tests, but 14 of them failed, the same ones,
> twice in a row
> [https://builds.apache.org/job/PreCommit-HIVE-Build/16744/testReport]
> [https://builds.apache.org/job/PreCommit-HIVE-Build/16774/testReport]
> {code:java}
> org.apache.hadoop.hive.metastore.TestObjectStore.catalogs (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testDatabaseOps (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testDeprecatedConfigIsOverwritten
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testDirectSQLDropParitionsCleanup
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testDirectSQLDropPartitionsCacheCrossSession
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testDirectSqlErrorMetrics
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testEmptyTrustStoreProps
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testMasterKeyOps
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testMaxEventResponse
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testPartitionOps
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testQueryCloseOnError
> (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testRoleOps (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testTableOps (batchId=230)
> org.apache.hadoop.hive.metastore.TestObjectStore.testUseSSLProperty
> (batchId=230)
> {code}
> all of the tests fail while initializing (see [^maven-test.txt]), dropping
> all objects (TestObjectStore.setUp:141->dropAllStoreObjects:776)
> {code:java}
> SELECT DISTINCT 'org.apache.hadoop.hive.metastore.model.MPartition' AS
> NUCLEUS_TYPE,A0.CREATE_TIME,A0.LAST_ACCESS_TIME,A0.PART_NAME,A0.WRITE_ID,A0.PART_ID,A0.PART_NAME
> AS NUCORDER0 FROM PARTITIONS A0 LEFT OUTER JOIN TBLS B0 ON A0.TBL_ID =
> B0.TBL_ID LEFT OUTER JOIN DBS C0 ON B0.DB_ID = C0.DB_ID WHERE B0.TBL_NAME = ?
> AND C0."NAME" = ? AND C0.CTLG_NAME = ? ORDER BY NUCORDER0 FETCH NEXT 100 ROWS
> ONLY
> {code}
> seems like a deadlock or stuff, all the tests are failed in 2min0sec, so an
> increased timeout wouldn't help here i think
> {code:java}
> javax.jdo.JDODataStoreException: Error executing SQL query "select
> "PARTITIONS"."PART_ID" from "PARTITIONS" inner join "TBLS" on
> "PARTITIONS"."TBL_ID" = "TBLS"."TBL_ID" and "TBLS"."TBL_NAME" = ? inner join
> "DBS" on "TBLS"."DB_ID" = "DBS"."DB_ID" and "DBS"."NAME" = ? where
> "DBS"."CTLG_NAME" = ? order by "PART_NAME" asc". at
> org.datanucleus.api.jdo.NucleusJDOHelper.getJDOExceptionForNucleusException(NucleusJDOHelper.java:543)
> ~[datanucleus-api-jdo-4.2.4.jar:?] at
> org.datanucleus.api.jdo.JDOQuery.executeInternal(JDOQuery.java:391)
> ~[datanucleus-api-jdo-4.2.4.jar:?] at
> org.datanucleus.api.jdo.JDOQuery.executeWithArray(JDOQuery.java:267)
> ~[datanucleus-api-jdo-4.2.4.jar:?] at
> org.apache.hadoop.hive.metastore.MetastoreDirectSqlUtils.executeWithArray(MetastoreDirectSqlUtils.java:61)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.MetaStoreDirectSql.executeWithArray(MetaStoreDirectSql.java:1882)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getPartitionIdsViaSqlFilter(MetaStoreDirectSql.java:759)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.MetaStoreDirectSql.getPartitions(MetaStoreDirectSql.java:673)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.ObjectStore$7.getSqlResult(ObjectStore.java:2677)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.ObjectStore$7.getSqlResult(ObjectStore.java:2673)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.ObjectStore$GetHelper.run(ObjectStore.java:3606)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.ObjectStore.getPartitionsInternal(ObjectStore.java:2689)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.ObjectStore.getPartitions(ObjectStore.java:2621)
> [classes/:?] at
> org.apache.hadoop.hive.metastore.TestObjectStore.dropAllStoreObjects(TestObjectStore.java:776)
> [test-classes/:?] at
> org.apache.hadoop.hive.metastore.TestObjectStore.setUp(TestObjectStore.java:141)
> [test-classes/:?] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native
> Method) ~[?:1.8.0_102] at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
> ~[?:1.8.0_102] at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> ~[?:1.8.0_102] at java.lang.reflect.Method.invoke(Method.java:498)
> ~[?:1.8.0_102] at
> org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47)
> [junit-4.11.jar:?] at
> org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
> [junit-4.11.jar:?] at
> org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44)
> [junit-4.11.jar:?] at
> org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:24)
> [junit-4.11.jar:?] at
> org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271)
> [junit-4.11.jar:?] at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70)
> [junit-4.11.jar:?] at
> org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner$3.run(ParentRunner.java:238)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner.access$000(ParentRunner.java:53)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229)
> [junit-4.11.jar:?] at
> org.junit.runners.ParentRunner.run(ParentRunner.java:309) [junit-4.11.jar:?]
> at
> org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:369)
> [surefire-junit4-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:275)
> [surefire-junit4-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:239)
> [surefire-junit4-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:160)
> [surefire-junit4-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:373)
> [surefire-booter-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:334)
> [surefire-booter-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:119)
> [surefire-booter-2.20.1.jar:2.20.1] at
> org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:407)
> [surefire-booter-2.20.1.jar:2.20.1]
> Caused by: java.sql.SQLTransactionRollbackException: A lock could not be
> obtained within the time requested at
> org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeQuery(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
> ~[HikariCP-2.6.1.jar:?] at
> com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
> ~[HikariCP-2.6.1.jar:?] at
> org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeQuery(ParamLoggingPreparedStatement.java:375)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.SQLController.executeStatementQuery(SQLController.java:552)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.performExecute(SQLQuery.java:645)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.query.Query.executeQuery(Query.java:1855)
> ~[datanucleus-core-4.1.17.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.executeWithArray(SQLQuery.java:807)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.api.jdo.JDOQuery.executeInternal(JDOQuery.java:368)
> ~[datanucleus-api-jdo-4.2.4.jar:?] ... 38 more
> Caused by: org.apache.derby.impl.jdbc.EmbedSQLException: A lock could not be
> obtained within the time requested at
> org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeQuery(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
> ~[HikariCP-2.6.1.jar:?] at
> com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
> ~[HikariCP-2.6.1.jar:?] at
> org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeQuery(ParamLoggingPreparedStatement.java:375)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.SQLController.executeStatementQuery(SQLController.java:552)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.performExecute(SQLQuery.java:645)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.query.Query.executeQuery(Query.java:1855)
> ~[datanucleus-core-4.1.17.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.executeWithArray(SQLQuery.java:807)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.api.jdo.JDOQuery.executeInternal(JDOQuery.java:368)
> ~[datanucleus-api-jdo-4.2.4.jar:?] ... 38 more Caused by:
> org.apache.derby.iapi.error.StandardException: A lock could not be obtained
> within the time requested at
> org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.services.locks.ConcurrentLockSet.zeroDurationLockObject(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.services.locks.AbstractPool.zeroDurationlockObject(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.services.locks.ConcurrentPool.zeroDurationlockObject(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.raw.xact.RowLocking2nohold.lockRecordForRead(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.heap.HeapController.lockRow(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockRowOnPage(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.btree.index.B2IRowLocking3._lockScanRow(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.btree.index.B2IRowLockingRR.lockScanRow(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.store.access.btree.BTreeScan.fetchNextGroup(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.BulkTableScanResultSet.reloadArray(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.BulkTableScanResultSet.getNextRowCore(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.NestedLoopJoinResultSet.getNextRowCore(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.getNextRowCore(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.SortResultSet.getRowFromResultSet(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.SortResultSet.getNextRowFromRS(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.SortResultSet.loadSorter(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.SortResultSet.openCore(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.ProjectRestrictResultSet.openCore(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.open(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
> ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeQuery(Unknown
> Source) ~[derby-10.10.2.0.jar:?] at
> com.zaxxer.hikari.pool.ProxyPreparedStatement.executeQuery(ProxyPreparedStatement.java:52)
> ~[HikariCP-2.6.1.jar:?] at
> com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeQuery(HikariProxyPreparedStatement.java)
> ~[HikariCP-2.6.1.jar:?] at
> org.datanucleus.store.rdbms.ParamLoggingPreparedStatement.executeQuery(ParamLoggingPreparedStatement.java:375)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.SQLController.executeStatementQuery(SQLController.java:552)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.performExecute(SQLQuery.java:645)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.store.query.Query.executeQuery(Query.java:1855)
> ~[datanucleus-core-4.1.17.jar:?] at
> org.datanucleus.store.rdbms.query.SQLQuery.executeWithArray(SQLQuery.java:807)
> ~[datanucleus-rdbms-4.1.19.jar:?] at
> org.datanucleus.api.jdo.JDOQuery.executeInternal(JDOQuery.java:368)
> ~[datanucleus-api-jdo-4.2.4.jar:?] ... 38 more
> {code}
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
