[JpaTransaction]: SqlExceptionHelper - Timeout trying to lock table

[thaingo]

Hi all, Leveraged on elide-spring to expose JSON API for models of parent - child relationship, and experienced the following issue:

2019-12-22 14:51:02.005  WARN 10535 --- [tp1970856042-25] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 50200, SQLState: HYT00
2019-12-22 14:51:02.007 ERROR 10535 --- [tp1970856042-25] o.h.engine.jdbc.spi.SqlExceptionHelper   : Timeout trying to lock table ; SQL statement:
insert into Shop (creationDate, customer_username, product, name) values (?, ?, ?, ?) [50200-197]
2019-12-22 14:51:02.010 ERROR 10535 --- [tp1970856042-25] c.y.e.d.j.t.AbstractJpaTransaction       : Caught entity manager exception during flush

javax.persistence.PessimisticLockException: could not execute statement
	at org.hibernate.internal.ExceptionConverterImpl.wrapLockException(ExceptionConverterImpl.java:273)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:108)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:181)
	at org.hibernate.internal.ExceptionConverterImpl.convert(ExceptionConverterImpl.java:188)
	at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1348)
	at org.hibernate.internal.SessionImpl.flush(SessionImpl.java:1331)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.orm.jpa.ExtendedEntityManagerCreator$ExtendedEntityManagerInvocationHandler.invoke(ExtendedEntityManagerCreator.java:368)
	at com.sun.proxy.$Proxy100.flush(Unknown Source)
	at com.yahoo.elide.datastores.jpa.transaction.AbstractJpaTransaction.flush(AbstractJpaTransaction.java:86)
	at com.yahoo.elide.core.datastore.wrapped.TransactionWrapper.flush(TransactionWrapper.java:111)
	at com.yahoo.elide.datastores.multiplex.MultiplexTransaction.lambda$flush$0(MultiplexTransaction.java:97)
	at java.util.LinkedHashMap$LinkedValues.forEach(LinkedHashMap.java:608)
	at com.yahoo.elide.datastores.multiplex.MultiplexTransaction.flush(MultiplexTransaction.java:97)
	at com.yahoo.elide.core.datastore.inmemory.InMemoryStoreTransaction.flush(InMemoryStoreTransaction.java:163)
	at com.yahoo.elide.Elide.handleRequest(Elide.java:207)
	at com.yahoo.elide.Elide.post(Elide.java:109)
	at com.yahoo.elide.spring.controllers.JsonApiController.elidePost(JsonApiController.java:69)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:888)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)

Current Behavior

When creating an entity/persistent object whose id is already existing in database via POST api, Elide will lock the database row storing entity having that very id and hold that lock for a long time as well (I am not sure whether the lock will be released later). Hence, adding in a child for the entity object will not be allowed. Update operation on that object is still possible though.

Steps to Reproduce (for bugs)

1. make POST request to create a customer with an id=abc
2. make a sequential POST request to create another customer with the same id, i.e. id=abc
3. next, make POST request to create a child entity of customer - shop
4. then get the following error

Caused by: org.h2.jdbc.JdbcSQLException: Timeout trying to lock table ; SQL statement:
insert into Shop (creationDate, customer_username, product, name) values (?, ?, ?, ?) [50200-197]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)
	at org.h2.message.DbException.get(DbException.java:168)
	at org.h2.command.Command.filterConcurrentUpdate(Command.java:316)
	at org.h2.command.Command.executeUpdate(Command.java:268)
	at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:199)
	at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:153)
	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:197)
	... 88 common frames omitted
Caused by: org.h2.jdbc.JdbcSQLException: Concurrent update in table "SHOP": another transaction has updated or deleted the same row [90131-197]
	at org.h2.message.DbException.getJdbcSQLException(DbException.java:357)

Context

I am doing this experiment to understand more of how a transaction is managed in Elide (including isolation level and concurrency). I suspect that issue might have something to do with custom data store. However, I am pretty sure that this has nothing to do with concurrent API request.

Your Environment

• Elide version used: 4.5.9 with custom data store
• Environment name and version (Java 1.8.0_152): 1.8.0_202
• Operating System and version: MacOS 10.15.2
• Link to your project: custom data store

Thanks, Thai

[thaingo]

I would like to add more information for clarification purpose: If I drop the custom data store, then I do not experience this issue any more.

I guess this issue is caused by improper creation of the beans needed custom data store @aklish

@Bean
    public DataStore dataStore(EntityManagerFactory entityManagerFactory) {
        DataStore store1 = new JpaDataStore(
            entityManagerFactory::createEntityManager, (NonJtaTransaction::new), Shop.class);
        CustomerStore customerStore = new CustomerStore(
            entityManagerFactory::createEntityManager,
            NonJtaTransaction::new
        );
        return new MultiplexManager(store1, customerStore);
    }

I am seeing that there are 2 entity managers, 2 NonJtaTransaction created from the above code segment, hence the issue. Your thoughts @aklish ?

PS: I also re-open the other issue for tracking purpose @aklish .

[aklish]

Good catch. I forgot to mention we use an entity manager supplier that allows us to share the entity manager within a single thread (across data store transactions). This code is not part of core Elide (but ought to be). Also, our version of this is using a pretty old Hibernate.

Can you send me another example branch? I can provide a PR against it to fix it. If this works, I'll open another PR against Elide to add the same Supplier to the JPAStore.

[thaingo]

Feel free to use the provided branch above @aklish Thanks.

[aklish]

I can reproduce. Thanks.

[aklish]

Ok. I created a class like this one:

public class SharedEntityManagerSupplier implements JpaDataStore.EntityManagerSupplier {
    ThreadLocal<EntityManager> entityManagerThreadLocal;
    EntityManagerFactory emf;

    public SharedEntityManagerSupplier(EntityManagerFactory factory) {
        this.emf = factory;
        entityManagerThreadLocal = new ThreadLocal<>();
    }

    @Override
    public EntityManager get() {
        EntityManager mgr = entityManagerThreadLocal.get();
        if (mgr == null || !mgr.isOpen()) {
            mgr = emf.createEntityManager();
            entityManagerThreadLocal.set(mgr);
        }
        return mgr;
    }
}

I used that as the supplier for both data stores:

    @Bean
    public DataStore dataStore(EntityManagerFactory entityManagerFactory) {
        SharedEntityManagerSupplier supplier = new SharedEntityManagerSupplier(entityManagerFactory);

        DataStore store1 = new JpaDataStore(
            supplier, (NonJtaTransaction::new), Shop.class);
        CustomerStore customerStore = new CustomerStore(
            supplier, NonJtaTransaction::new
        );
        return new MultiplexManager(store1, customerStore);
    }

If this works for you, let's keep this issue open but close the other one. I think Elide should have a general solution for this. We'll add it likely in our next sprint.

[thaingo]

It works @aklish and thanks for your time.