Uploaded image for project: 'Derby'
  1. Derby
  2. DERBY-7079

Getting 'ERROR 40XL1: A lock could not be obtained within the time requested' immediately, no 60 seconds lock time out

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.15.1.3
    • Fix Version/s: None
    • Component/s: SQL
    • Labels:
      None
    • Bug behavior facts:
      Crash, Performance, Wrong query result

      Description

      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?

       

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                s0m3body1 Martin Hajduch
              • Votes:
                0 Vote for this issue
                Watchers:
                2 Start watching this issue

                Dates

                • Created:
                  Updated: