Record deadlock issue in 2.0.2

[Kareem Jabr]

I am facing this exception a lot now,

in context with path [/aa-sport] threw exception [com.orientechnologies.orient.core.exception.ODatabaseException: Error on retrieving record #27:165831 (cluster: event)] with root cause

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:1784)

        at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.readRecord(OAbstractPaginatedStorage.java:1424)

        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)

        at com.orientechnologies.orient.core.tx.OTransactionNoTx.loadRecord(OTransactionNoTx.java:80)

        at com.orientechnologies.orient.core.db.document.ODatabaseDocumentTx.load(ODatabaseDocumentTx.java:1437)

        at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.readRecord(ONetworkProtocolBinary.java:1453)

        at com.orientechnologies.orient.server.network.protocol.binary.ONetworkProtocolBinary.executeRequest(ONetworkProtocolBinary.java:346)

        at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:216)

        at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:65)

I have a web app running on tomcat 7.0.59 and 2.0.2 OrientDB.

I am initializing the DB once tomcat starts

db = getOObjectDatabaseTx();

db.setAutomaticSchemaGeneration(true);

db.getEntityManager().registerEntityClasses("com.sport.server.model");

public OObjectDatabaseTx getOObjectDatabaseTx() {

return OObjectDatabasePool.global().acquire(PropertiesManager.getInstance().getProperty(ENDPOINT_URL), PropertiesManager.getInstance().getProperty(DB_USERNAME),

PropertiesManager.getInstance().getProperty(DB_PASSWORD));

}

Please help me in this.. And let me know if I am doing something wrong here. I have a scheduler running to update the DB every couple of secs. This exception happens when I try to read from the DB while writing is occurring. I believe..

[Andrey Lomakin]

Hi,

I do not think that it is deadlock, it is timeout exception could you set storage.record.lockTimeout property to 200000 to double check ?

--

---
You received this message because you are subscribed to the Google Groups "OrientDB" group.
To unsubscribe from this group and stop receiving emails from it, send an email to orient-databa...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

--

Best regards,
Andrey Lomakin.

[Kareem Jabr]

Hi,

Thanks for your help.

I tried the following after seeing it somewhere here:

OGlobalConfiguration.STORAGE_LOCK_TIMEOUT.setValue(5 * 60 * 1000);

but the same issue occurs.

How and where to set storage.record.lockTimeout? Do I have to do it in <properties> inside the orientdb-server-config.xml?

[Kareem Jabr]

Hi, I already set in the properties of  orientdb-server-config.xml and I removed from my code this part:

 OGlobalConfiguration.STORAGE_LOCK_TIMEOUT.setValue(5 * 60 * 1000);

I am also facing another issue when stopping the orientdb server I still can see the process running when I execute: ps aux | grep java, so I have to kill the process each time. especially when the timeout exception occurs. 

Thanks

On Saturday, February 21, 2015 at 12:47:53 PM UTC+4, Kareem Jabr wrote:

Hi,

Thanks for your help.

I tried the following after seeing it somewhere here:

OGlobalConfiguration.STORAGE_LOCK_TIMEOUT.setValue(5 * 60 * 1000);

but the same issue occurs.

How and where to set storage.record.lockTimeout? Do I have to do it in <properties> inside the orientdb-server-config.xml?

On Friday, February 20, 2015 at 9:44:58 AM UTC+4, Andrey Lomakin wrote:

[Andrey Lomakin]

HI,

Could you send me thread dump then ?

[Kareem Jabr]

Full thread dump OpenJDK 64-Bit Server VM (24.65-b04 mixed mode):

"OrientDB WAL Flush Task (sport)" daemon prio=10 tid=0x00007f3fa8246000 nid=0x77f2 waiting on condition [0x00007f3feadea000]

   java.lang.Thread.State: TIMED_WAITING (parking)

   at sun.misc.Unsafe.park(Native Method)

   - parking to wait for  <0x00000000ec997480> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

   at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)

   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)

   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)

   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)

   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)

   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   at java.lang.Thread.run(Thread.java:745)

"OrientDB <- BinaryClient (/127.0.0.1:59789)" daemon prio=10 tid=0x00007f3fb0006800 nid=0x20aa runnable [0x00007f3fea9e6000]

   java.lang.Thread.State: RUNNABLE

   at java.net.SocketInputStream.socketRead0(Native Method)

   at java.net.SocketInputStream.read(SocketInputStream.java:152)

   at java.net.SocketInputStream.read(SocketInputStream.java:122)

   at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

   at java.io.BufferedInputStream.read(BufferedInputStream.java:254)

   - locked <0x00000000e05b74b0> (a java.io.BufferedInputStream)

   at java.io.DataInputStream.readByte(DataInputStream.java:265)

   at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinary.readByte(OChannelBinary.java:73)

   at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:207)

   at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:69)

"OrientDB <- BinaryClient (/127.0.0.1:59788)" daemon prio=10 tid=0x00007f3fb0005800 nid=0x20a9 runnable [0x00007f3feace9000]

   java.lang.Thread.State: RUNNABLE

   at java.net.SocketInputStream.socketRead0(Native Method)

   at java.net.SocketInputStream.read(SocketInputStream.java:152)

   at java.net.SocketInputStream.read(SocketInputStream.java:122)

   at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

   at java.io.BufferedInputStream.read(BufferedInputStream.java:254)

   - locked <0x00000000e0592c08> (a java.io.BufferedInputStream)

   at java.io.DataInputStream.readByte(DataInputStream.java:265)

   at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinary.readByte(OChannelBinary.java:73)

   at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:207)

   at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:69)

"OrientDB <- BinaryClient (/127.0.0.1:59703)" daemon prio=10 tid=0x00007f3fb0004000 nid=0x1fc5 runnable [0x00007f3feaeeb000]

   java.lang.Thread.State: RUNNABLE

   at java.net.SocketInputStream.socketRead0(Native Method)

   at java.net.SocketInputStream.read(SocketInputStream.java:152)

   at java.net.SocketInputStream.read(SocketInputStream.java:122)

   at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

   at java.io.BufferedInputStream.read(BufferedInputStream.java:254)

   - locked <0x00000000e03e69a0> (a java.io.BufferedInputStream)

   at java.io.DataInputStream.readByte(DataInputStream.java:265)

   at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinary.readByte(OChannelBinary.java:73)

   at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:207)

   at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:69)

"OrientDB <- BinaryClient (/127.0.0.1:59632)" daemon prio=10 tid=0x00007f3fb0003000 nid=0x1f77 runnable [0x00007f3feb1f5000]

   java.lang.Thread.State: RUNNABLE

   at java.net.SocketInputStream.socketRead0(Native Method)

   at java.net.SocketInputStream.read(SocketInputStream.java:152)

   at java.net.SocketInputStream.read(SocketInputStream.java:122)

   at java.io.BufferedInputStream.fill(BufferedInputStream.java:235)

   at java.io.BufferedInputStream.read(BufferedInputStream.java:254)

   - locked <0x00000000e029b8e8> (a java.io.BufferedInputStream)

   at java.io.DataInputStream.readByte(DataInputStream.java:265)

   at com.orientechnologies.orient.enterprise.channel.binary.OChannelBinary.readByte(OChannelBinary.java:73)

   at com.orientechnologies.orient.server.network.protocol.binary.OBinaryNetworkProtocolAbstract.execute(OBinaryNetworkProtocolAbstract.java:207)

   at com.orientechnologies.common.thread.OSoftThread.run(OSoftThread.java:69)

"OrientDB Write Cache Flush Task (sport)" daemon prio=10 tid=0x00007f3fa824d000 nid=0x1f49 waiting on condition [0x00007f3feaff3000]

   java.lang.Thread.State: TIMED_WAITING (parking)

   at sun.misc.Unsafe.park(Native Method)

   - parking to wait for  <0x00000000e0149638> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

   at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:226)

   at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2082)

   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1090)

   at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:807)

   at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1068)

   at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)

   at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

   at java.lang.Thread.run(Thread.java:745)

"DestroyJavaVM" prio=10 tid=0x00007f3ff400a800 nid=0x1f2d waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"OrientDB ONetworkProtocolHttpDb listen at 0.0.0.0:2480-2490" prio=10 tid=0x00007f3ff44c2000 nid=0x1f3a runnable [0x00007f3feb345000]

   java.lang.Thread.State: RUNNABLE

   at java.net.PlainSocketImpl.socketAccept(Native Method)

   at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)

   at java.net.ServerSocket.implAccept(ServerSocket.java:530)

   at java.net.ServerSocket.accept(ServerSocket.java:498)

   at com.orientechnologies.orient.server.network.OServerNetworkListener.run(OServerNetworkListener.java:191)

"OrientDB ONetworkProtocolBinary listen at 0.0.0.0:2424-2430" prio=10 tid=0x00007f3ff449c000 nid=0x1f39 runnable [0x00007f3feb446000]

   java.lang.Thread.State: RUNNABLE

   at java.net.PlainSocketImpl.socketAccept(Native Method)

   at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:398)

   at java.net.ServerSocket.implAccept(ServerSocket.java:530)

   at java.net.ServerSocket.accept(ServerSocket.java:498)

   at com.orientechnologies.orient.server.network.OServerNetworkListener.run(OServerNetworkListener.java:191)

"Timer-0" daemon prio=10 tid=0x00007f3ff43ea000 nid=0x1f38 in Object.wait() [0x00007f3feb74f000]

   java.lang.Thread.State: TIMED_WAITING (on object monitor)

   at java.lang.Object.wait(Native Method)

   - waiting on <0x00000000e0142770> (a java.util.TaskQueue)

   at java.util.TimerThread.mainLoop(Timer.java:552)

   - locked <0x00000000e0142770> (a java.util.TaskQueue)

   at java.util.TimerThread.run(Timer.java:505)

"Service Thread" daemon prio=10 tid=0x00007f3ff40ac000 nid=0x1f36 runnable [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=10 tid=0x00007f3ff40a9800 nid=0x1f35 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=10 tid=0x00007f3ff40a6800 nid=0x1f34 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x00007f3ff40a4800 nid=0x1f33 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=10 tid=0x00007f3ff4077800 nid=0x1f32 in Object.wait() [0x00007f3ff0321000]

   java.lang.Thread.State: WAITING (on object monitor)

   at java.lang.Object.wait(Native Method)

   - waiting on <0x00000000e008d6b0> (a java.lang.ref.ReferenceQueue$Lock)

   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)

   - locked <0x00000000e008d6b0> (a java.lang.ref.ReferenceQueue$Lock)

   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)

   at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" daemon prio=10 tid=0x00007f3ff4075800 nid=0x1f31 in Object.wait() [0x00007f3ff0422000]

   java.lang.Thread.State: WAITING (on object monitor)

   at java.lang.Object.wait(Native Method)

   - waiting on <0x00000000e008d240> (a java.lang.ref.Reference$Lock)

   at java.lang.Object.wait(Object.java:503)

   at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)

   - locked <0x00000000e008d240> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x00007f3ff4071800 nid=0x1f30 runnable

"GC task thread#0 (ParallelGC)" prio=10 tid=0x00007f3ff4020000 nid=0x1f2e runnable

"GC task thread#1 (ParallelGC)" prio=10 tid=0x00007f3ff4022000 nid=0x1f2f runnable

"VM Periodic Task Thread" prio=10 tid=0x00007f3ff40b6800 nid=0x1f37 waiting on condition

JNI global references: 172

Heap

 PSYoungGen      total 137216K, used 86126K [0x00000000f5500000, 0x00000000ff600000, 0x0000000100000000)

  eden space 126976K, 64% used [0x00000000f5500000,0x00000000fa513a20,0x00000000fd100000)

  from space 10240K, 40% used [0x00000000fec00000,0x00000000ff008000,0x00000000ff600000)

  to   space 18944K, 0% used [0x00000000fd100000,0x00000000fd100000,0x00000000fe380000)

 ParOldGen       total 320512K, used 220346K [0x00000000e0000000, 0x00000000f3900000, 0x00000000f5500000)

  object space 320512K, 68% used [0x00000000e0000000,0x00000000ed72e8e8,0x00000000f3900000)

 PSPermGen       total 21504K, used 17944K [0x00000000d5a00000, 0x00000000d6f00000, 0x00000000e0000000)

  object space 21504K, 83% used [0x00000000d5a00000,0x00000000d6b862c8,0x00000000d6f00000)

--

---
You received this message because you are subscribed to a topic in the Google Groups "OrientDB" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/orient-database/INf_ennAN7o/unsubscribe.
To unsubscribe from this group and all its topics, send an email to orient-databa...@googlegroups.com.

[Andrey Lomakin]

Sorry, I do not see any deadlock there ((

Could you also create issue about this bug ?

[alexander anguiano]

i also was getting this.   It seems when you do thing using the graphdb it cause problems

My queries and updates where like this

select * from groups where @rid = #12:3

I change them to this

select * from #12:3

I had updates like this

update table set mfield = 12 where @rid = #14:4

i changed the to this

UPDATE (select expand(in('Target')) from #14:4) set tags = 'mytag'

Also, i don't think you can parameterize that so you have to do this'

UPDATE (select expand(in('Target')) from #%s) set tags = '%s'

[Kareem Jabr]

Im using object api not the graph. And it happens when i clear multiple lists of nested objects, like, match.getGoals.clear then I call match.getGoals.addAll(newGoalsList)  i see in the errors log orientdb exception regarding not found records #27.6765 some id. And then the timeout exception lock. I will post the thread dump when the exception occurs to get a clear idea about the error.

Thanks

[Jing Chen]

I am getting this error too. Any progress on this issue? My application is running OrientDB 2.0.4

Jing

[Luca Garulli]

Hi guys,

Sorry could anybody provide a test case we can analyze and reproduce the problem? I'd like to have this fixed in 2.0.5 ;-)

Lvc@

On 6 March 2015 at 20:20, Jing Chen <jingj...@gmail.com> wrote:

I am getting this error too. Any progress on this issue? My application is running OrientDB 2.0.4

Jing

--

---

You received this message because you are subscribed to the Google Groups "OrientDB" group.

To unsubscribe from this group and stop receiving emails from it, send an email to orient-databa...@googlegroups.com.

[Kareem Jabr]

Hi,

I get this issue when I do massive and continues parentModel.ChildModelList.clear() on nested lists of an object and immediately calling addAll(new List) and this parentModel class has many nested lists represented as LinkList in DB.

I am not getting this issue now as I modified the logic to reduced amount of calling list.clear(). And prevented any read attempt while the deletion process is being executed to avoid any locking or deadLocking exception. That might have solved my issue until now. 

Thanks,

Kareem

--

---
You received this message because you are subscribed to a topic in the Google Groups "OrientDB" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/orient-database/INf_ennAN7o/unsubscribe.
To unsubscribe from this group and all its topics, send an email to orient-databa...@googlegroups.com.