Hello, I am facing 40XL1 error when I try to insert rows into a table with an identity column. Identity column has been created using "id integer generated by default as identity (START WITH 100, INCREMENT BY 1)". This is also the primary key for the table. Start with 100 is used because I use 1 to 99 range to insert deterministic values for test cases.
I am using latest Derby i.e 10.13 as in memory database. Inserts are issued from callable tasks running in a thread pool executor. I am using JPA with Guice persist 4.0. Hibernate 5.1.3 is being used as JPA provider. C3P0 is being used as database connection pooler with auto commit off. Transaction isolation level has been set to repeatable read. I have not touched Derby locking levels, so the default one is used. I have enabled hiberante logs to ensure that transactions are committed as and when expected. This is the stack trace of the exception: ERROR 40XL1: A lock could not be obtained within the time requested at org.apache.derby.iapi.error.StandardException.newException( StandardException.java:290) at org.apache.derby.iapi.error.StandardException.newException( StandardException.java:285) at org.apache.derby.impl.sql.catalog.SequenceUpdater. tooMuchContentionException(SequenceUpdater.java:188) at org.apache.derby.impl.sql.catalog.SequenceUpdater. getCurrentValueAndAdvance(SequenceUpdater.java:430) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl. getCurrentValueAndAdvance(DataDictionaryImpl.java:10364) at org.apache.derby.impl.sql.execute.BaseActivation. getCurrentValueAndAdvance(BaseActivation.java:765) at org.apache.derby.impl.sql.execute.InsertResultSet. getSetAutoincrementValue(InsertResultSet.java:574) at org.apache.derby.impl.sql.execute.BaseActivation. getSetAutoincrementValue(BaseActivation.java:744) at org.apache.derby.exe.ac802dc2f6x015cx19c4x040bx00000946a9007.e0(Unknown Source) at org.apache.derby.impl.services.reflect.DirectCall. invoke(ReflectGeneratedClass.java:101) at org.apache.derby.impl.sql.execute.RowResultSet. getNextRowCore(RowResultSet.java:150) at org.apache.derby.impl.sql.execute.NormalizeResultSet.getNextRowCore( NormalizeResultSet.java:188) at org.apache.derby.impl.sql.execute.DMLWriteResultSet.getNextRowCore( DMLWriteResultSet.java:148) at org.apache.derby.impl.sql.execute.InsertResultSet.getNextRowCore( InsertResultSet.java:1082) at org.apache.derby.impl.sql.execute.InsertResultSet.open( InsertResultSet.java:451) at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt( GenericPreparedStatement.java:472) at org.apache.derby.impl.sql.GenericPreparedStatement.execute( GenericPreparedStatement.java:351) at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement( EmbedStatement.java:1339) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement( EmbedPreparedStatement.java:1709) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeLargeUpdate( EmbedPreparedStatement.java:320) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeUpdate( EmbedPreparedStatement.java:309) at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate( NewProxyPreparedStatement.java:147) at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate( ResultSetReturnImpl.java:204) at org.hibernate.id.insert.AbstractSelectingDelegate.performInsert( AbstractSelectingDelegate.java:45) at org.hibernate.persister.entity.AbstractEntityPersister.insert( AbstractEntityPersister.java:2853) at org.hibernate.persister.entity.AbstractEntityPersister.insert( AbstractEntityPersister.java:3424) at org.hibernate.action.internal.EntityIdentityInsertAction.execute( EntityIdentityInsertAction.java:81) at org.hibernate.engine.spi.ActionQueue.execute(ActionQueue.java:619) at org.hibernate.engine.spi.ActionQueue.addResolvedEntityInsertAction( ActionQueue.java:273) at org.hibernate.engine.spi.ActionQueue.addInsertAction( ActionQueue.java:254) at org.hibernate.engine.spi.ActionQueue.addAction(ActionQueue.java:299) at org.hibernate.event.internal.AbstractSaveEventListener.addInsertAction( AbstractSaveEventListener.java:318) at org.hibernate.event.internal.AbstractSaveEventListener. performSaveOrReplicate(AbstractSaveEventListener.java:275) at org.hibernate.event.internal.AbstractSaveEventListener.performSave( AbstractSaveEventListener.java:182) at org.hibernate.event.internal.AbstractSaveEventListener. saveWithGeneratedId(AbstractSaveEventListener.java:113) at org.hibernate.jpa.event.internal.core.JpaPersistEventListener. saveWithGeneratedId(JpaPersistEventListener.java:67) at org.hibernate.event.internal.DefaultPersistEventListener. entityIsTransient(DefaultPersistEventListener.java:189) at org.hibernate.event.internal.DefaultPersistEventListener.onPersist( DefaultPersistEventListener.java:132) at org.hibernate.event.internal.DefaultPersistEventListener.onPersist( DefaultPersistEventListener.java:58) at org.hibernate.internal.SessionImpl.firePersist(SessionImpl.java:778) at org.hibernate.internal.SessionImpl.persist(SessionImpl.java:751) at org.hibernate.internal.SessionImpl.persist(SessionImpl.java:756) at org.hibernate.jpa.spi.AbstractEntityManagerImpl.persist( AbstractEntityManagerImpl.java:1146) at com.kwery.dao.JobExecutionDao.save(JobExecutionDao.java:37) at com.kwery.dao.JobExecutionDao$$EnhancerByGuice$$6b3bcf96. CGLIB$save$6(<generated>) at com.kwery.dao.JobExecutionDao$$EnhancerByGuice$$6b3bcf96$$ FastClassByGuice$$2b148b1d.invoke(<generated>) at com.google.inject.internal.cglib.proxy.$MethodProxy. invokeSuper(MethodProxy.java:228) at com.google.inject.internal.InterceptorStackCallback$ InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75) at com.google.inject.persist.jpa.JpaLocalTxnInterceptor.invoke( JpaLocalTxnInterceptor.java:70) at com.google.inject.internal.InterceptorStackCallback$ InterceptedMethodInvocation.proceed(InterceptorStackCallback.java:75) at com.google.inject.internal.InterceptorStackCallback.intercept( InterceptorStackCallback.java:55) at com.kwery.dao.JobExecutionDao$$EnhancerByGuice$$6b3bcf96. save(<generated>) at com.kwery.services.job.Job.saveJobExecutionStart(Job.java:324) at com.kwery.services.job.Job.call(Job.java:108) at com.kwery.services.job.Job.call(Job.java:36) at java.util.concurrent.FutureTask.run(FutureTask.java:266) 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:745) Once I started facing the error, I did some peeking around Derby source code. The place where the exception is thrown, has this comment: "We try to get a sequence number. The SequenceGenerator method is synchronized so only one writer should be in there at a time. Lock contention is possible if someone has selected from SYSSEQUENCES contrary to our advice. In that case, we raise a TOO MUCH CONTENTION exception." I enabled Derby sql statement logging and confirmed that my code is not generating any selects from SYSSEQUENCES table. I followed the steps in the derby lock debugging wiki as well as FAQs to debug the issue. Along with some source code instrumentation, below are my findings: The transaction that fails with lock error has XID 616. Thu May 18 09:46:00 IST 2017 Thread[pool-4-thread-1,5,main] (XID = 616), (SESSIONID = 5), (DATABASE = memory:kwery_db_test), (DRDAID = null), Failed Statement is: insert into job_execution (id, execution_end, execution_id, execution_start, job_id_fk, status) values (default, ?, ?, ?, ?, ?) with 5 parameters begin parameter #1: null :end parameter begin parameter #2: 9e1f6163-9614-42c4-9a31-682b6a07c343 :end parameter begin parameter #3: 1495080960190 :end parameter begin parameter #4: 16 :end parameter begin parameter #5: ONGOING :end parameter If fails to acquire the below lock: DEBUG foo OUTPUT: Lockable Record id=14 Page(1,Container(0, 1024)) Qualifier=X CompatibilitySpace=org.apache.derby.impl.services.locks.LockSpace@24ff7409 Group=<null> Timeout(ms)=0 Thread=Thread[pool-4-thread-1,5,main](Got from my source code instrumentation) It fails because the lock is being held by XID = 614(Got from my source code instrumentation) This is the query corresponding to transaction 614: Thu May 18 09:46:00 IST 2017 Thread[pool-4-thread-2,5,main] (XID = 614), (SESSIONID = 7), (DATABASE = memory:kwery_db_test), (DRDAID = null), Executing prepared statement: values identity_val_local() :End prepared statement At this point, I also printed the lock table, and this is what I see in there: XID |TYPE |MODE|LOCKCOUNT|LOCKNAME |STATE|TABLETYPE / LOCKOBJ |INDEXNAME / CONTAINER_ID / (MODE for LATCH only) |TABLENAME / CONGLOM_ID | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- 618 |TABLE |IX |1 |Tablelock |GRANT|S |NULL |SYSSEQUENCES | 614 |TABLE |IS |0 |Tablelock |WAIT |S |NULL |SYSCONGLOMERATES | 614 |TABLE |IS |0 |Tablelock |WAIT |S |NULL |SYSTABLES | 614 |TABLE |IS |0 |Tablelock |WAIT |S |NULL |SYSCONSTRAINTS | 614 |TABLE |IS |0 |Tablelock |WAIT |S |NULL |SYSKEYS | 614 |ROW |S |0 |(6,19) |WAIT |S |NULL |SYSCOLUMNS | 614 |ROW |S |0 |(1,14) |WAIT |S |NULL |SYSSEQUENCES | 614 |ROW |S |0 |(1,12) |WAIT |S |NULL |SYSFOREIGNKEYS | 614 |ROW |S |0 |(8,8) |WAIT |S |NULL |SYSCONGLOMERATES | 614 |ROW |S |0 |(8,7) |WAIT |S |NULL |SYSCONGLOMERATES | 614 |ROW |S |0 |(2,6) |WAIT |S |NULL |SYSCONSTRAINTS | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- XID 618 which is holding a lock on the SYSSEQUENCES table is actually a child of 616, the transaction which fails. I guess this is part of the flow where in the SYSSEQUENCES table is locked first before updating the rows(my assertion, correct me if I am wrong here). Can someone please help me in figuring out what is going wrong here and what is the fix? I am sure Derby supports more concurrency than this(I have only two to four concurrent threads inserting rows). -- Cheers, Abhi https://getkwery.com/