[1.2.7] perf : Could not execute JDBC batch update under high load

[Carl]

Hello,

I'm updating the techempower benchmark application and I noticed crashes when trying to do updates under high load.
It looks like there is deadlock at some point

I tested my app using ab (500 requests done by 20 concurrent threads)
   ab -l -c20 -n500 http://localhost:8080/updates?queries=50
Each request performs 50 updates.

(I use mysql 5.6.15 embedded in easyphp)

Here's an excerpt of the code:

    public static void updates(int queries) {
        // Bounds check.
        if (queries > 500) {
            queries = 500;
        }
        if (queries < 1) {
            queries = 1;
        }
        final World[] worlds = new World[queries];

        // Run the query the number of times requested.
        for (int i = 0; i < queries; i++) {
            final long id = random.nextInt(TEST_DATABASE_ROWS) + 1;
            World item = World.findById(id);
            worlds[i] = item;
            item.randomNumber = new Long(random.nextInt(TEST_DATABASE_ROWS) + 1);
            item.save();
        }
        renderJSON(worlds);
    }


Here's the complete stacktrace
@6im4p3knk
Internal Server Error (500) for request GET /updates?queries=50

Execution exception (In /app/controllers/Application.java around line 75)
PersistenceException occured : org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update

play.exceptions.JavaExecutionException: org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch u
pdate
        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:237)
        at Invocation.HTTP Request(Play!)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: Could not execute J
DBC batch update
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1389)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1317)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1323)
        at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:965)
        at play.db.jpa.JPABase._save(JPABase.java:41)
        at play.db.jpa.GenericModel.save(GenericModel.java:215)
        at controllers.Application.updates(Application.java:75)
        at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:557)
        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:508)
        at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:484)
        at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:479)
        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:161)
        ... 1 more
Caused by: org.hibernate.exception.LockAcquisitionException: Could not execute JDBC batch update
        at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:107)
        at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:275)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:268)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:185)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:34
5)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:51)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1216)
        at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:962)
        ... 9 more
Caused by: java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2034)
        at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1468)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:70)
        at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:268)
        ... 15 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; tr
y restarting transaction
        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:1064)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4096)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4028)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2490)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2651)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2683)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2144)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2444)
        at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1997)
        ... 18 more
14:22:18,769 ERROR ~

The complete code is available on github.

[Carl]

The issue also occurs with the 1.3.x github branch.

More info about the issue

14:50:59,325 INFO  ~ Application 'play1' is now started !
14:50:59,385 INFO  ~ Listening for HTTP on port 8080 ...
14:51:18,377 WARN  ~ SQL Error: 1213, SQLState: 40001
14:51:18,387 ERROR ~ Deadlock found when trying to get lock; try restarting transaction
14:51:27,246 ERROR ~

@6im52p0hi

Internal Server Error (500) for request GET /updates?queries=50

Execution exception (In /app/controllers/Application.java around line 75)

PersistenceException occured : org.hibernate.exception.LockAcquisitionException: Deadlock found when trying to get lock;
 try restarting transaction

play.exceptions.JavaExecutionException: org.hibernate.exception.LockAcquisitionException: Deadlock found when trying to

get lock; try restarting transaction

        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:236)
        at Invocation.HTTP Request(Play!)
Caused by: javax.persistence.PersistenceException: org.hibernate.exception.LockAcquisitionException: Deadlock found when

 trying to get lock; try restarting transaction

        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1367)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1295)
        at org.hibernate.ejb.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1301)
        at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:984)
        at play.db.jpa.JPABase._save(JPABase.java:40)
        at play.db.jpa.GenericModel.save(GenericModel.java:224)
        at controllers.Application.updates(Application.java:75)
        at play.mvc.ActionInvoker.invokeWithContinuation(ActionInvoker.java:556)
        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:507)
        at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:483)
        at play.mvc.ActionInvoker.invokeControllerMethod(ActionInvoker.java:478)
        at play.mvc.ActionInvoker.invoke(ActionInvoker.java:160)
        ... 1 more
Caused by: org.hibernate.exception.LockAcquisitionException: Deadlock found when trying to get lock; try restarting tran
saction
        at org.hibernate.exception.internal.SQLExceptionTypeDelegate.convert(SQLExceptionTypeDelegate.java:94)
        at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:49)

        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:125)
        at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:110)
        at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementPr
oxyHandler.java:129)
        at org.hibernate.engine.jdbc.internal.proxy.AbstractProxyHandler.invoke(AbstractProxyHandler.java:81)
        at com.sun.proxy.$Proxy17.executeUpdate(Unknown Source)
        at org.hibernate.engine.jdbc.batch.internal.NonBatchingBatch.addToBatch(NonBatchingBatch.java:56)
        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3016)
        at org.hibernate.persister.entity.AbstractEntityPersister.updateOrInsert(AbstractEntityPersister.java:2918)
        at org.hibernate.persister.entity.AbstractEntityPersister.update(AbstractEntityPersister.java:3247)
        at org.hibernate.action.internal.EntityUpdateAction.execute(EntityUpdateAction.java:140)
        at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:362)
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:354)
        at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:276)
        at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.ja
va:352)
        at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:52)
        at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1214)
        at org.hibernate.ejb.AbstractEntityManagerImpl.flush(AbstractEntityManagerImpl.java:981)
        ... 9 more

Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; tr
y restarting transaction

        at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
        at com.mysql.jdbc.Util.getInstance(Util.java:384)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1064)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4232)
        at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4164)
        at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2615)
        at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2776)
        at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2838)
        at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2082)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2334)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2262)
        at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2246)
        at org.hibernate.engine.jdbc.internal.proxy.AbstractStatementProxyHandler.continueInvocation(AbstractStatementPr
oxyHandler.java:122)
        ... 23 more
14:51:27,594 WARN  ~ SQL Error: 1213, SQLState: 40001
14:51:27,611 ERROR ~ Deadlock found when trying to get lock; try restarting transaction
14:51:27,640 ERROR ~

[Carl]

On Thursday, July 3, 2014 2:53:23 PM UTC+2, Carl wrote:

The issue also occurs with the 1.3.x github branch.

The problem is due to INNODB inner working.

Still, it would be nice to have an enhancer to deal with it.
Wait, there is ! 

I wonder why this not included in the release.
Anyway, time to create a new module...

[Carl]

I wonder why this not included in the release.
Anyway, time to create a new module...

The new module, transaction-retry, is available here

[Andy Lewis]

Thanks for posting this.