You are viewing a plain text version of this content. The canonical link for it is here.
Posted to derby-dev@db.apache.org by "Richard N. Hillegas (Jira)" <ji...@apache.org> on 2020/06/02 22:41:00 UTC
[jira] [Commented] (DERBY-7079) Getting 'ERROR 40XL1: A lock could
not be obtained within the time requested' immediately, no 60 seconds lock
time out
[ https://issues.apache.org/jira/browse/DERBY-7079?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17124445#comment-17124445 ]
Richard N. Hillegas commented on DERBY-7079:
--------------------------------------------
Have you looked at the Debugging Deadlocks section linked from the Developer's Guide page you cited above? If you follow the advice there, then you should be able to see which statements are deadlocking with one another. Hope this helps.
> 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)