Uploaded image for project: 'Hibernate Search'
  1. HSEARCH-2916

Avoid random failures in TestRunnerStandalone.runPerformanceTest

    Details

      Description

      The failures happen randomly and are caused by concurrency issues:

      javax.persistence.PessimisticLockException: could not execute statement
      	at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:249)
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:103)
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:157)
      	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:164)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1443)
      	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:493)
      	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3207)
      	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2413)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:467)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:156)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68)
      	at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:53)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: org.hibernate.PessimisticLockException: could not execute statement
      	at org.hibernate.dialect.H2Dialect$3.convert(H2Dialect.java:352)
      	at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:42)
      	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:111)
      	at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:97)
      	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:178)
      	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198)
      	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457)
      	at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
      	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
      	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1437)
      	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:493)
      	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3207)
      	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2413)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:467)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:156)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68)
      	at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:53)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: org.h2.jdbc.JdbcSQLException: Timeout trying to lock table ; SQL statement:
      update book set publicationDate=?, rating=?, summary=?, title=?, totalSold=? where id=? [50200-178]
      	at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
      	at org.h2.message.DbException.get(DbException.java:167)
      	at org.h2.command.Command.filterConcurrentUpdate(Command.java:301)
      	at org.h2.command.Command.executeUpdate(Command.java:256)
      	at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)
      	at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)
      	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
      	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
      	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
      	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198)
      	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457)
      	at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
      	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
      	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1437)
      	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:493)
      	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3207)
      	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2413)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:467)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:156)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68)
      	at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:53)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:748)
      Caused by: org.h2.jdbc.JdbcSQLException: Concurrent update in table "BOOK": another transaction has updated or deleted the same row [90131-178]
      	at org.h2.message.DbException.getJdbcSQLException(DbException.java:344)
      	at org.h2.message.DbException.get(DbException.java:178)
      	at org.h2.message.DbException.get(DbException.java:154)
      	at org.h2.mvstore.db.MVPrimaryIndex.remove(MVPrimaryIndex.java:170)
      	at org.h2.mvstore.db.MVTable.removeRow(MVTable.java:584)
      	at org.h2.table.Table.updateRows(Table.java:456)
      	at org.h2.command.dml.Update.update(Update.java:146)
      	at org.h2.command.CommandContainer.update(CommandContainer.java:79)
      	at org.h2.command.Command.executeUpdate(Command.java:254)
      	at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:158)
      	at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:144)
      	at com.zaxxer.hikari.pool.ProxyPreparedStatement.executeUpdate(ProxyPreparedStatement.java:61)
      	at com.zaxxer.hikari.pool.HikariProxyPreparedStatement.executeUpdate(HikariProxyPreparedStatement.java)
      	at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:175)
      	at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:45)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3198)
      	at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:3077)
      	at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3457)
      	at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:145)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:589)
      	at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:463)
      	at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:337)
      	at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:39)
      	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1437)
      	at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:493)
      	at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:3207)
      	at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:2413)
      	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:467)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:156)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.access$100(JdbcResourceLocalTransactionCoordinatorImpl.java:38)
      	at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:231)
      	at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:68)
      	at org.hibernate.search.test.performance.task.AbstractTask.run(AbstractTask.java:53)
      	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
      	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
      	at java.lang.Thread.run(Thread.java:748)
      

      Source: http://ci.hibernate.org/job/hibernate-search-master/org.hibernate$hibernate-search-performance-orm/1115/testReport/junit/org.hibernate.search.test.performance/TestRunnerStandalone/runPerformanceTest/

      The exact cause is the update tasks in that test, such as UpdateBookRatingTask or UpdateBookTotalSoldTask. Those tasks execute concurrently, and they pick an entity ID randomly to perform the update on. In smoke tests, there are very few entities (10, I think) and thus a conflict is very likely.

        Attachments

          Activity

            People

            • Assignee:
              yrodiere Yoann Rodière
              Reporter:
              yrodiere Yoann Rodière
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: