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/
