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

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • 10.15.1.3
    • None
    • SQL
    • None
    • 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

          relates to

          Bug - A problem which impairs or prevents the functions of the product. DERBY-6975 ERROR 40XL1: A lock could not be obtained within the time requested

          • Major - Major loss of function.
          • Open

          Activity

            People

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

              Dates

                Created:
                Updated: