OTimeoutException: Can not lock record for 2000 ms Error in 2.0.4

[Jing Chen]

Hi OrientDB team,

We are using OrientDB 2.0.4 in CentOS. Our Web application runs Orientdb as an embedded server with plocal connetion. We got some errors like this from our production server yesterday. Here is the stack trace:

com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #14:452944 (cluster: ndexproperty)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.executeReadRecord(ODatabaseDocumentTx.java:1605)
    at com.orientechnologies.orient.core.tx.OTransactionNoTx.loadRecord(OTransactionNoTx.java:80)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.load(ODatabaseDocumentTx.java:1424)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.load(ODatabaseDocumentTx.java:117)
    at com.orientechnologies.orient.core.id.ORecordId.getRecord(ORecordId.java:313)
    at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:93)
    at com.orientechnologies.orient.core.db.record.ridbag.embedded.OEmbeddedRidBag$EntriesIterator.next(OEmbeddedRidBag.java:65)
    at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:40)
    at com.orientechnologies.orient.core.command.traverse.OTraverseMultiValueProcess.process(OTraverseMultiValueProcess.java:28)
    at com.orientechnologies.orient.core.command.traverse.OTraverse.next(OTraverse.java:105)
    at com.orientechnologies.orient.core.command.traverse.OTraverse.hasNext(OTraverse.java:75)
    at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getPropertiesFromDocument(NetworkDAO.java:864)
    at org.ndexbio.common.models.dao.orientdb.NetworkDAO.setNetworkSummary(NetworkDAO.java:1440)
    at org.ndexbio.common.models.dao.orientdb.NetworkDAO.getNetworkSummary(NetworkDAO.java:1448)
    at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findAllNetworks(NetworkSearchDAO.java:118)
    at org.ndexbio.common.models.dao.orientdb.NetworkSearchDAO.findNetworks(NetworkSearchDAO.java:66)
    at org.ndexbio.rest.services.NetworkAService.searchNetwork(NetworkAService.java:822)
    at sun.reflect.GeneratedMethodAccessor91.invoke(Unknown Source)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:137)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:296)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:250)
    at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:237)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:356)
    at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:179)
    at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:220)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:56)
    at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:51)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:501)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:171)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1070)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:611)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:316)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Caused by: com.orientechnologies.common.concur.OTimeoutException: Can not lock record for 2000 ms. seems record is deadlocked by other record
    at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.acquireReadLock(OAbstractPaginatedStorage.java:1308)
    at com.orientechnologies.orient.core.tx.OTransactionAbstract.lockRecord(OTransactionAbstract.java:120)
    at com.orientechnologies.orient.core.id.ORecordId.lock(ORecordId.java:282)
    at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.lockRecord(OAbstractPaginatedStorage.java:1779)
    at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.readRecord(OAbstractPaginatedStorage.java:1425)
    at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.readRecord(OAbstractPaginatedStorage.java:697)
    at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.executeReadRecord(ODatabaseDocumentTx.java:1572)
    ... 49 more

The record that the application was trying to read is this:
+-------------------------------------------------------------------------------------------------+
| Document - @class: NdexProperty                          @rid: #14:452944      @version: 10     |
+-------------------------------------------------------------------------------------------------+
|                     Name | Value                                                                |
+-------------------------------------------------------------------------------------------------+
|                    value | http://purl.org/pc2/6/reactome_human                                 |
|                    dType | String                                                               |
|                 out_prop | baseTerm#20:4179426{name:Source,id:7491152,in_BaseTerms:#26:501,in_prop:#14:452944} v9 |
|             in_ndexProps | network#26:501{UUID:d9e38fcb-c429-11e4-bcc4-000c29cb28fb,createdTime:Fri Mar 06 09:54:35 PST 2015,modificationTime:Thu Apr 09 16:32:06 PDT 2015,name:Bile salt and organic anion SLC transporters,description:This network belongs to the Reactome Human Pathway Database and was obtained from Pathway Commons (PC2 v.4),edgeCount:59,nodeCount:58,version:v46 (23-SEP-2013),out_BaseTerms:[size=-1],isDeleted:false,isLocked:false,isComplete:true,visibility:PUBLIC,out_networkNodes:[size=-1],out_networkEdges:[size=-1],out_citations:[size=16],out_networkNS:[size=30],out_ndexProps:[size=3],sourceFormat:SIF,provenance:{"uri":"http://www.ndexbio.org/network/d9e38fcb-c429-11e4-bcc4-000c29cb28fb","creationEvent":{"inputs":null,"startedAtTime":1425664475624,"endedAtTime":1425664489103,"eventType":"FILE_UPLOAD","properties":[{"name":"filename","value":"f1d7c030-c425-11e4-bcc4-000c29cb28fb.sif","type":"SimplePropertyValuePair"}],"type":"ProvenanceEvent"},"properties":[],"type":"ProvenanceEntity"},in_admin:#18:132} v510 |
+-------------------------------------------------------------------------------------------------+

This record itself was not modified after it was created. However, it has a incoming link "ndexProps" from #26:501. record #26:501 was modified (maybe more than once) by other threads right before the read. That update was in its own transaction. Could that trigger this Exception?

Thanks,
Jing

[Pawel K.]

Do you use record lock in UPDATE commands ?

Maybe it's related to 

https://github.com/orientechnologies/orientdb/issues/3631

Pawel