Uploaded image for project: 'Hive'
  1. Hive
  2. HIVE-21550

TestObjectStore tests are flaky - A lock could not be obtained within the time requested

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Major
    • Resolution: Fixed
    • None
    • 4.0.0-alpha-1
    • None
    • None

    Description

      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

      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)
      

      all of the tests fail while initializing (see maven-test.txt), dropping all objects (TestObjectStore.setUp:141->dropAllStoreObjects:776)

      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
      
      

      seems like a deadlock or stuff, all the tests are failed in 2min0sec, so an increased timeout wouldn't help here i think

      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
      
      

      Attachments

        1. TEST-230_UTBatch_standalone-metastore__metastore-server_20_tests-TEST-org.apache.hadoop.hive.metastore.TestObjectStore.xml
          749 kB
          László Bodor
        2. surefire_derby_stacktrace.log
          59 kB
          László Bodor
        3. screenshot-builds.apache.org-2019.03.30-12-38-32.png
          156 kB
          László Bodor
        4. org.apache.hadoop.hive.metastore.TestObjectStore-output.txt
          2.46 MB
          László Bodor
        5. maven-test.txt
          24 kB
          László Bodor
        6. HIVE-21550.repro.patch
          2 kB
          László Bodor
        7. HIVE-21550.02.patch
          8 kB
          László Bodor
        8. HIVE-21550.01.patch
          8 kB
          László Bodor

        Activity

          People

            abstractdog László Bodor
            abstractdog László Bodor
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: