Identity column and 40XL1 error

classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

Identity column and 40XL1 error

Abhirama
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).

--
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

John English-3
On 18/05/2017 08:29, Abhirama wrote:
> 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.

Usual reason is some other query has a lock on the table -- maybe you
did a SELECT involving that table and forgot to close the ResultSet?
--
John English
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Abhirama
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

John English-3
On 18/05/2017 12:20, Abhirama wrote:
> As you can see from my post, lock is denied because of "values
> identity_val_local()" issued by a competing insert on the same table.
> This is also asserted by the the fact that, in application, if I
> synchronise all the offending inserts(only inserts, not selects), I do
> not get a lock exception. I find it really hard to believe that derby
> locks out on a couple of concurrent inserts.

Oops, sorry, didn't read your post closely enough...
--
John English
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Rick Hillegas-3
In reply to this post by Abhirama
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick



On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi


Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Abhirama
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something? 

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Rick Hillegas-3
On 5/18/17 9:12 PM, Abhirama wrote:
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something?
Hi Abhi,

Yes, that should work. It will be slightly different than IDENTITY_VAL_LOCAL() if an identity-generating statement encounters an error which rolls back its updates. In that case, there will be holes in the sequence. But that may be good enough for Hibernate's purposes. I can't say.

Again, I wonder about the semantics of IDENTITY_VAL_LOCAL() in a highly concurrent, INSERT-intensive application. It is not clear to me what a given session expects from this function. The JDBC approach to retrieving the keys generated by the current session is to use java.sql.Statement.getGeneratedKeys().

Hope this helps,
-Rick

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Cheers,
Abhi


Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Abhirama
Hello Rick,

With your guidance I was able to dig more into the problem.

IDENTITY_VAL_LOCAL() is not being issued by hibernate but by Derby itself. Hibernate does use getGeneratedKeys. When it issues getGeneratedKeys(), the call is being directed to 

public final java.sql.ResultSet getGeneratedKeys() throws SQLException {
checkStatus();
if (autoGeneratedKeysResultSet == null)
return null;
else {
execute("VALUES IDENTITY_VAL_LOCAL()", true, false, Statement.NO_GENERATED_KEYS, null, null);
return results;
}
}

present in org.apache.derby.impl.jdbc.EmbedStatement class. As you can see, this executes "VALUES IDENTITY_VAL_LOCAL()" SQL statement. 

Is getGeneratedKeys internally supported by Derby using IDENTITY_VAL_LOCAL()? What am I missing here? Is there a way around this?

On Sat, May 20, 2017 at 5:49 AM, Rick Hillegas <[hidden email]> wrote:
On 5/18/17 9:12 PM, Abhirama wrote:
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something?
Hi Abhi,

Yes, that should work. It will be slightly different than IDENTITY_VAL_LOCAL() if an identity-generating statement encounters an error which rolls back its updates. In that case, there will be holes in the sequence. But that may be good enough for Hibernate's purposes. I can't say.

Again, I wonder about the semantics of IDENTITY_VAL_LOCAL() in a highly concurrent, INSERT-intensive application. It is not clear to me what a given session expects from this function. The JDBC approach to retrieving the keys generated by the current session is to use java.sql.Statement.getGeneratedKeys().


Hope this helps,
-Rick

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Cheers,
Abhi





--
Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Rick Hillegas-3
Hi Abhi,

Thanks for investigating further. You have uncovered a defect in Derby's implementation of Statement.getGeneratedKeys(). The defect must have been introduced when we re-implemented identity columns on top of sequence generators. I have reproduced the problem which you are seeing and have opened the following bug report: https://issues.apache.org/jira/browse/DERBY-6934. I have attached a repro to that report.

I don't have any clever workaround to recommend. It sounds as though your application does not need to call Statement.getGeneratedKeys(). I don't know if there is a way to prevent Hibernate from calling that method.

Thanks for reporting this problem. I will give some thought to how we can fix it.

Thanks,
-Rick


On 5/20/17 5:34 AM, Abhirama wrote:
Hello Rick,

With your guidance I was able to dig more into the problem.

IDENTITY_VAL_LOCAL() is not being issued by hibernate but by Derby itself. Hibernate does use getGeneratedKeys. When it issues getGeneratedKeys(), the call is being directed to 

public final java.sql.ResultSet getGeneratedKeys() throws SQLException {
checkStatus();
if (autoGeneratedKeysResultSet == null)
return null;
else {
execute("VALUES IDENTITY_VAL_LOCAL()", true, false, Statement.NO_GENERATED_KEYS, null, null);
return results;
}
}

present in org.apache.derby.impl.jdbc.EmbedStatement class. As you can see, this executes "VALUES IDENTITY_VAL_LOCAL()" SQL statement. 

Is getGeneratedKeys internally supported by Derby using IDENTITY_VAL_LOCAL()? What am I missing here? Is there a way around this?

On Sat, May 20, 2017 at 5:49 AM, Rick Hillegas <[hidden email]> wrote:
On 5/18/17 9:12 PM, Abhirama wrote:
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something?
Hi Abhi,

Yes, that should work. It will be slightly different than IDENTITY_VAL_LOCAL() if an identity-generating statement encounters an error which rolls back its updates. In that case, there will be holes in the sequence. But that may be good enough for Hibernate's purposes. I can't say.

Again, I wonder about the semantics of IDENTITY_VAL_LOCAL() in a highly concurrent, INSERT-intensive application. It is not clear to me what a given session expects from this function. The JDBC approach to retrieving the keys generated by the current session is to use java.sql.Statement.getGeneratedKeys().


Hope this helps,
-Rick

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Cheers,
Abhi





--
Cheers,
Abhi


Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Rick Hillegas-3
In reply to this post by Abhirama
Hi Abhi,

Here is one more idea. I believe that you said that you are running an in-memory database. That means that you do not need to worry about leaking pre-allocated sequence numbers when your application exits. You can try setting the pre-allocation range to the maximum number with the following system property:

    -Dderby.language.sequence.preallocator=2147483647

When I try that setting, my repro program runs without any lock contention.

Hope this helps,
-Rick

On 5/20/17 5:34 AM, Abhirama wrote:
Hello Rick,

With your guidance I was able to dig more into the problem.

IDENTITY_VAL_LOCAL() is not being issued by hibernate but by Derby itself. Hibernate does use getGeneratedKeys. When it issues getGeneratedKeys(), the call is being directed to 

public final java.sql.ResultSet getGeneratedKeys() throws SQLException {
checkStatus();
if (autoGeneratedKeysResultSet == null)
return null;
else {
execute("VALUES IDENTITY_VAL_LOCAL()", true, false, Statement.NO_GENERATED_KEYS, null, null);
return results;
}
}

present in org.apache.derby.impl.jdbc.EmbedStatement class. As you can see, this executes "VALUES IDENTITY_VAL_LOCAL()" SQL statement. 

Is getGeneratedKeys internally supported by Derby using IDENTITY_VAL_LOCAL()? What am I missing here? Is there a way around this?

On Sat, May 20, 2017 at 5:49 AM, Rick Hillegas <[hidden email]> wrote:
On 5/18/17 9:12 PM, Abhirama wrote:
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something?
Hi Abhi,

Yes, that should work. It will be slightly different than IDENTITY_VAL_LOCAL() if an identity-generating statement encounters an error which rolls back its updates. In that case, there will be holes in the sequence. But that may be good enough for Hibernate's purposes. I can't say.

Again, I wonder about the semantics of IDENTITY_VAL_LOCAL() in a highly concurrent, INSERT-intensive application. It is not clear to me what a given session expects from this function. The JDBC approach to retrieving the keys generated by the current session is to use java.sql.Statement.getGeneratedKeys().


Hope this helps,
-Rick

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Cheers,
Abhi





--
Cheers,
Abhi


Reply | Threaded
Open this post in threaded view
|

Re: Identity column and 40XL1 error

Abhirama
Rick,

Thanks for your help in debugging the problem.

I run in memory only while testing, actual application does use persistent file system backed database. I did try to use different preallocator ranges (100, 1000 etc), it did not make any difference.

On Sun, May 21, 2017 at 12:20 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

Here is one more idea. I believe that you said that you are running an in-memory database. That means that you do not need to worry about leaking pre-allocated sequence numbers when your application exits. You can try setting the pre-allocation range to the maximum number with the following system property:

    -Dderby.language.sequence.preallocator=<a href="tel:(214)%20748-3647" value="+12147483647" target="_blank">2147483647

When I try that setting, my repro program runs without any lock contention.

Hope this helps,
-Rick

On 5/20/17 5:34 AM, Abhirama wrote:
Hello Rick,

With your guidance I was able to dig more into the problem.

IDENTITY_VAL_LOCAL() is not being issued by hibernate but by Derby itself. Hibernate does use getGeneratedKeys. When it issues getGeneratedKeys(), the call is being directed to 

public final java.sql.ResultSet getGeneratedKeys() throws SQLException {
checkStatus();
if (autoGeneratedKeysResultSet == null)
return null;
else {
execute("VALUES IDENTITY_VAL_LOCAL()", true, false, Statement.NO_GENERATED_KEYS, null, null);
return results;
}
}

present in org.apache.derby.impl.jdbc.EmbedStatement class. As you can see, this executes "VALUES IDENTITY_VAL_LOCAL()" SQL statement. 

Is getGeneratedKeys internally supported by Derby using IDENTITY_VAL_LOCAL()? What am I missing here? Is there a way around this?

On Sat, May 20, 2017 at 5:49 AM, Rick Hillegas <[hidden email]> wrote:
On 5/18/17 9:12 PM, Abhirama wrote:
Rick,

My code is not explicitly firing IDENTITY_VAL_LOCAL() call, my best guess is hibernate, but I can confirm this by enabling hibernate logging. Will do that and confirm.

I assume hibernate is issuing this to get the id of the last inserted row so that it can hydrate the ORM model with this data. As per your recommendation, if IDENTITY_VAL_LOCAL is not used, how do I get the last inserted id? I read about SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() and it says it will give the next value assigned to an identity column, not the last generated one. Are you saying something along the lines of subtract 1 from this value and use that or am I missing something?
Hi Abhi,

Yes, that should work. It will be slightly different than IDENTITY_VAL_LOCAL() if an identity-generating statement encounters an error which rolls back its updates. In that case, there will be holes in the sequence. But that may be good enough for Hibernate's purposes. I can't say.

Again, I wonder about the semantics of IDENTITY_VAL_LOCAL() in a highly concurrent, INSERT-intensive application. It is not clear to me what a given session expects from this function. The JDBC approach to retrieving the keys generated by the current session is to use java.sql.Statement.getGeneratedKeys().


Hope this helps,
-Rick

On Fri, May 19, 2017 at 5:18 AM, Rick Hillegas <[hidden email]> wrote:
Hi Abhi,

You may have tripped across a problem with the IDENTITY_VAL_LOCAL() function. When identity columns were re-worked to use sequence generators, concurrency tests were run which involved many writers, that is, many sessions which concurrently issued INSERT statements. I don't recall much testing done with competing sessions which issued IDENTITY_VAL_LOCAL() calls.

In the case when you have multiple concurrent writers, what is the meaning you expect from IDENTITY_VAL_LOCAL()? It is possible that the SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() system function may give you a result you can work with. It is likely that SYSCS_UTIL.SYSCS_PEEK_AT_IDENTITY() will play better with the underlying sequence generator.

If you can script the problem, please open a bug report.

Hope this helps,
-Rick




On 5/18/17 2:20 AM, Abhirama wrote:
As you can see from my post, lock is denied because of "values identity_val_local()" issued by a competing insert on the same table. This is also asserted by the the fact that, in application, if I synchronise all the offending inserts(only inserts, not selects), I do not get a lock exception. I find it really hard to believe that derby locks out on a couple of concurrent inserts.

On Thu, May 18, 2017 at 1:03 PM, John English <[hidden email]> wrote:
On 18/05/2017 08:29, Abhirama wrote:
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.

Usual reason is some other query has a lock on the table -- maybe you did a SELECT involving that table and forgot to close the ResultSet?
--
John English



--
Cheers,
Abhi





--
Cheers,
Abhi





--
Cheers,
Abhi





--