[
https://issues.apache.org/jira/browse/DERBY-7079?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17126246#comment-17126246
]
Richard N. Hillegas commented on DERBY-7079:
--------------------------------------------
Linking to derby-6975. This is another example of locking issues with
autogenerated keys.
> Getting 'ERROR 40XL1: A lock could not be obtained within the time requested'
> immediately, no 60 seconds lock time out
> ----------------------------------------------------------------------------------------------------------------------
>
> Key: DERBY-7079
> URL: https://issues.apache.org/jira/browse/DERBY-7079
> Project: Derby
> Issue Type: Bug
> Components: SQL
> Affects Versions: 10.15.1.3
> Reporter: Martin Hajduch
> Priority: Major
>
> Our application uses embedded Derby 10.15.1.3.
> Rarely, we are getting 'ERROR 40XL1: A lock could not be obtained within the
> time requested'.
> We of course read:
> [http://db.apache.org/derby/docs/10.8/devguide/cdevconcepts28436.html]
> According to the documentation, default value of '_derby.locks.waitTimeout_'
> is 60 seconds. We have not changed this value. Our understanding is, that if
> a transaction cannot obtain required lock within 60 seconds, it should time
> out.
>
> Now, this is the exception our server application is getting:
>
> 2020-05-14 13:56:21,295 ERROR null
> assyst.datarepository.session.AbstractSession.messageReceived(?:?) -
> Session[13, de40b97b-109c-4c14-bd38-f8ca3463026d, CAX
> Explorer-W7-DE-CRRNTRLS, /127.0.0.1:49193]: error processing message
> cadcam.attr.OverwriteBinaryData
> assyst.datarepository.interfaces.b.d:
> assyst.datarepository.jdbc.PreparedStmt$SqlEx: failed executeUpdate() on
> insert into assyst.TESTDP_STP_m (version, modified_ms, last_modified,
> itm_name, name_upr, BBI, BLI, BRI, BTI, DES, DES_U, ESS, FLP, FLD, GAP, GIX,
> HPD, HPTT, IDX, MYF, NAP, OPC, GAT, PCE, PCE_U, PPL, PPF, PPX, PPY, ROP, RUF,
> XST, YST, STY, STY_U, TLT, UFC) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
> ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
> with params [1, 1589457381232, 2020-05-14 13:56:21.232,
> 7c525a9e-dcdd-46a9-a43e-6c717a839e52, 7C525A9E-DCDD-46A9-A43E-6C717A839E52,
> 0, 0, 0, 0, AY-GS-BLAZER, AY-GS-BLAZER, 0, 0, 0, 0, 0, 0, 0, 7, 0, 0, 1, 0,
> AY-BLAZER-RTO-E, AY-BLAZER-RTO-E, 0, 1, 9186088, -3725635, 0.0, 0.0, 0.0,
> 0.0, AY-GS-BLAZER-E, AY-GS-BLAZER-E, 0.0, 1]
> at assyst.datarepository.jdbc.TaskExecutor.b(Unknown Source)
> at assyst.datarepository.jdbc.TaskExecutor.execute(Unknown Source)
> at assyst.datarepository.jdbc.JdbcRepository.execute(Unknown Source)
> at assyst.datarepository.jdbc.JdbcRepository.saveBinaryData(Unknown Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy5.saveBinaryData(Unknown Source)
> at
> assyst.datarepository.validating.ValidatingRepository.saveBinaryData(Unknown
> Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy3.saveBinaryData(Unknown Source)
> at
> assyst.datarepository.blobparser.BlobParserRepositoryBD.saveBinaryData(Unknown
> Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy5.saveBinaryData(Unknown Source)
> at
> assyst.datarepository.virtual.VirtualDataRepository.saveBinaryData(Unknown
> Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy5.saveBinaryData(Unknown Source)
> at
> assyst.datarepository.virtual.HistoryLoggingRepository.saveBinaryData(Unknown
> Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy5.saveBinaryData(Unknown Source)
> at
> assyst.datarepository.virtual.VirtualDataRepository.saveBinaryData(Unknown
> Source)
> at jdk.internal.reflect.GeneratedMethodAccessor101.invoke(Unknown Source)
> at
> java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> at java.base/java.lang.reflect.Method.invoke(Method.java:566)
> at assyst.cfg.InvocationHandlerImpl.invokeImpl(Unknown Source)
> at assyst.cfg.LoggingInvocationHandler.b(Unknown Source)
> at assyst.datarepository.server.ILInvocationHandler.invokeImpl(Unknown
> Source)
> at assyst.cfg.InvocationHandlerImpl.invoke(Unknown Source)
> at com.sun.proxy.$Proxy5.saveBinaryData(Unknown Source)
> at assyst.datarepository.handler.attr.AttrUtils.saveBinaryData(Unknown
> Source)
> at
> assyst.datarepository.handler.cadcam.attr.SaveBinaryData.saveBinaryDataS(Unknown
> Source)
> at
> assyst.datarepository.handler.cadcam.attr.SaveBinaryData.saveBinaryDataS(Unknown
> Source)
> at assyst.datarepository.handler.cadcam.attr.SaveBinaryData.b(Unknown Source)
> at assyst.datarepository.handler.SaveBinaryData.handleMessageImpl(Unknown
> Source)
> at assyst.datarepository.handler.SaveBinaryData.handleMessageImpl(Unknown
> Source)
> at
> assyst.datarepository.handler.SimpleMessageHandlerImpl.handleMessage(Unknown
> Source)
> at assyst.datarepository.session.ForwardingSessionImpl.b(Unknown Source)
> at assyst.datarepository.session.AbstractSession.messageReceived(Unknown
> Source)
> at assyst.datarepository.server.BinaryConnectionHandler.run(Unknown Source)
> at assyst.datarepository.server.ConnectionTypeDispatcher.run(Unknown Source)
> at assyst.datarepository.server.ConnectionTypeDispatcher.run(Unknown Source)
> at java.base/java.lang.Thread.run(Thread.java:834)
> Caused by: assyst.datarepository.jdbc.PreparedStmt$SqlEx: failed
> executeUpdate() on insert into assyst.TESTDP_STP_m (version, modified_ms,
> last_modified, itm_name, name_upr, BBI, BLI, BRI, BTI, DES, DES_U, ESS, FLP,
> FLD, GAP, GIX, HPD, HPTT, IDX, MYF, NAP, OPC, GAT, PCE, PCE_U, PPL, PPF, PPX,
> PPY, ROP, RUF, XST, YST, STY, STY_U, TLT, UFC) values (?, ?, ?, ?, ?, ?, ?,
> ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?,
> ?, ?, ?, ?) with params [1, 1589457381232, 2020-05-14 13:56:21.232,
> 7c525a9e-dcdd-46a9-a43e-6c717a839e52, 7C525A9E-DCDD-46A9-A43E-6C717A839E52,
> 0, 0, 0, 0, AY-GS-BLAZER, AY-GS-BLAZER, 0, 0, 0, 0, 0, 0, 0, 7, 0, 0, 1, 0,
> AY-BLAZER-RTO-E, AY-BLAZER-RTO-E, 0, 1, 9186088, -3725635, 0.0, 0.0, 0.0,
> 0.0, AY-GS-BLAZER-E, AY-GS-BLAZER-E, 0.0, 1]
> at assyst.datarepository.jdbc.PreparedStmt.executeUpdate(Unknown Source)
> at assyst.datarepository.jdbc.d.m.b(Unknown Source)
> at assyst.datarepository.jdbc.d.c.execute(Unknown Source)
> ... 70 more
> *Caused by: java.sql.SQLTransactionRollbackException: A lock could not be
> obtained within the time requested*
> *at
> org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:100)*
> *at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Util.java:230)*
> *at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:431)*
> *at
> org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:360)*
> *at
> org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2405)*
> *at
> org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:88)*
> *at
> org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1436)*
> *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)*
> *... 73 more*
> *Caused by: ERROR 40XL1: A lock could not be obtained within the time
> requested*
> *at
> org.apache.derby.shared.common.error.StandardException.newException(StandardException.java:300)*
> *at
> org.apache.derby.shared.common.error.StandardException.newException(StandardException.java:295)*
> *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:10323)*
> *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.acdf51ae7dx0172x1305x8049x000003b3ea30c.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:1344)*
> *... 76 more*
>
>
> This operation on the server side is triggered by a client application,
> sending specific request to our server.
> From our other logs, we can see that a series of similar operations
> _(creation of 'data items', rows in a table, with different values)_, started
> at 2020-05-14 13:56:20,662. Nine of these operations went through. Tenth
> failed with the above error. Timestamp of this tenth operation is 2020-05-14
> 13:56:21,295. Both applications _(client & server)_ run on the same computer.
> I.e. the failure comes less then 2 seconds after the INSERT statement has
> been executed.
> These operations are executed sequentially. Nine INSERTs go through, tenth
> fails. There is almost no other load on the database during that time either.
> Is there anything we could do to generate more useful debug output, showing
> why the failure happens instantly, instead of waiting 60 seconds for the lock?
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
