locks on pure query activities

analyzing the dynamic behavior we can see from the thread dump that a lot of our threads that are just doing simple queries (just selects, no update or delete ...) show locks like these (question is: why there are locks and how could we get rid of that):

log1:


"qtp1523553211-271" #271 prio=5 os_prio=0 tid=0x000000004fcb3800 nid=0x440 waiting for monitor entry [0x00000000559ae000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.objectdb.o.LFL.UB(LFL.java:1098)
        - waiting to lock <0x0000000202239c10> (a com.objectdb.o.LFL)
        at com.objectdb.o.PAG.au(PAG.java:928)
        at com.objectdb.o.PGC.C(PGC.java:281)
        - locked <0x00000002029df788> (a java.lang.Object)
        at com.objectdb.o.SNP.G(SNP.java:436)
        at com.objectdb.o.RTT.l(RTT.java:127)
        at com.objectdb.o.RST.l(RST.java:24)
        at com.objectdb.o.RTT.D(RTT.java:179)
        at com.objectdb.o.RST.s(RST.java:121)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.RST.B(RST.java:93)
        at com.objectdb.o.RTT.l(RTT.java:132)
        at com.objectdb.o.RST.l(RST.java:24)
        at com.objectdb.o.RTT.D(RTT.java:179)
        at com.objectdb.o.RST.s(RST.java:121)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.RST.B(RST.java:93)
        at com.objectdb.o.RTT.l(RTT.java:132)
        at com.objectdb.o.RST.l(RST.java:24)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.TSM.e(TSM.java:86)
        at com.objectdb.o.RTT.D(RTT.java:177)
        at com.objectdb.o.RST.s(RST.java:121)
        at com.objectdb.o.PGT.q(PGT.java:109)
        at com.objectdb.o.RST.B(RST.java:93)
        at com.objectdb.o.RTT.l(RTT.java:132)
        at com.objectdb.o.RST.l(RST.java:24)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.MST.a0(MST.java:609)
        at com.objectdb.o.MST.Vm(MST.java:565)
        at com.objectdb.o.PLN.Vm(PLN.java:517)
        at com.objectdb.o.TAI.A(TAI.java:201)
        at com.objectdb.o.TAI.UI(TAI.java:134)
        at com.objectdb.o.TQI.UI(TQI.java:54)
        at com.objectdb.o.PRG.ag(PRG.java:687)
        at com.objectdb.o.PRG.af(PRG.java:555)
        at com.objectdb.o.QRM.Vo(QRM.java:286)
        at com.objectdb.o.MST.Vo(MST.java:988)
        at com.objectdb.o.WRA.Vo(WRA.java:311)
        at com.objectdb.o.WSM.Vo(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:719)
        - locked <0x0000000633b83180> (a com.objectdb.jdo.PMImpl)
        at com.agile.hummingbird.API.handleQuery(API.java:3020)
        at com.agile.hummingbird.API.directRequest(API.java:852)
        at com.agile.hummingbird.API.handleWebSocketRequest(API.java:614)
        at com.agile.hummingbird.WebSocketServerListener.onWebSocketText(WebSocketServerListener.java:123)
        at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:128)
        at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65)
        at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:122)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:161)
        at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
        at org.eclipse.jetty.websocket.common.extensions.AbstractExtension.nextIncomingFrame(AbstractExtension.java:163)
        at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.nextIncomingFrame(PerMessageDeflateExtension.java:105)
        at org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension.forwardIncoming(CompressExtension.java:136)
        at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.incomingFrame(PerMessageDeflateExtension.java:85)
        at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
        at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
        at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:632)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:480)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
        at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:
        - None


or:

"qtp1523553211-264" #264 prio=5 os_prio=0 tid=0x000000004f95f000 nid=0x1d28 runnable [0x00000000550ae000]
   java.lang.Thread.State: RUNNABLE
        at com.objectdb.o.BQI.VM(BQI.java:151)
        at com.objectdb.o.MQI.VM(MQI.java:145)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.GQI.UI(GQI.java:148)
        at com.objectdb.o.SQI.UI(SQI.java:108)
        at com.objectdb.o.PRG.ag(PRG.java:687)
        at com.objectdb.o.PRG.af(PRG.java:555)
        at com.objectdb.o.QRM.Vo(QRM.java:286)
        at com.objectdb.o.MST.Vo(MST.java:988)
        at com.objectdb.o.WRA.Vo(WRA.java:311)
        at com.objectdb.o.WSM.Vo(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:719)
        - locked <0x00000007b974f4f0> (a com.objectdb.jdo.PMImpl)
        at com.agile.hummingbird.CT_Container.computeContainer(CT_Container.java:161)
        at com.agile.hummingbird.API.handleGetContainer(API.java:2484)
        at com.agile.hummingbird.API.directRequest(API.java:786)
        at com.agile.hummingbird.API.handleWebSocketRequest(API.java:614)
        at com.agile.hummingbird.WebSocketServerListener.onWebSocketText(WebSocketServerListener.java:123)
        at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:128)
        at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65)
        at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:122)
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:161)
        at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
        at org.eclipse.jetty.websocket.common.extensions.AbstractExtension.nextIncomingFrame(AbstractExtension.java:163)
        at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.nextIncomingFrame(PerMessageDeflateExtension.java:105)
        at org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension.forwardIncoming(CompressExtension.java:136)
        at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.incomingFrame(PerMessageDeflateExtension.java:85)
        at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
        at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
        at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:632)
        at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:480)
        at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
        at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:
        - None

Access to the underlying database file is synchronized with that lock.

We may be able to remove that lock in future versions of ObjectDB, but it is unclear if this would improve the performance of your application, as apparently I/O operations are the bottleneck.

Some possible improvements:

• If the database is on a HDD then switching to a fast SSD could help.
• Increasing the page cache may help.
• By running replications of your database on separate disks you may be able to refer read only queries to replicated slaves.

• we already have a 2GByte page cache for a 30 GByte database file. Should we increase ?
• Database is on SSD

• We can see that the more threads are doing exactly the same query we step into more and more situations like the first heap dump where all are waiting to lock com.objectdb.o.LFL

objectdb configuration (we have a 16 cpu cores, 32 GByte machine):

<!-- ObjectDB Configuration -->

<objectdb>

<general>
  <temp path="$temp" threshold="64mb" />
  <network inactivity-timeout="0" />
  <url-history size="50" user="true" password="true" />
  <log path="$objectdb/log/" max="8mb" stdout="false" stderr="false" />
  <log-archive path="$objectdb/log/archive/" retain="90" />
  <logger name="*" level="info" />
</general>

<database>
  <size initial="256kb" resize="256kb" page="2kb" />
  <recovery enabled="true" sync="false" path="." max="128mb" />
  <recording enabled="false" sync="false" path="." mode="write" />
  <locking version-check="true" />
  <processing cache="2048mb" max-threads="48" />
        <index-update enabled="true" priority="40" />
  <query-cache results="1024mb" programs="500" />
  <extensions drop="temp,tmp" />
</database>

<entities>
  <enhancement agent="false" reflection="warning" />
  <cache ref="weak" level2="4096mb" />
        <fetch hollow="true" />
  <persist serialization="false" />
  <cascade-persist always="auto" on-persist="false" on-commit="true" />
  <dirty-tracking arrays="true" />
</entities>

<schema>
</schema>

<server>
  <connection port="6136" max="100" />
  <data path="$objectdb/db" />
        <embedded-server enabled="true" />
  <!--
  <replication url="objectdb://localhost/test.odb;user=admin;password=admin" />
  -->
</server>

<users>
  <user username="admin" password="admin">
   <dir path="/" permissions="access,modify,create,delete" />
  </user>
  <user username="$default" password="$$$###">
   <dir path="/$user/" permissions="access,modify,create,delete">
    <quota directories="5" files="20" disk-space="5mb" />
   </dir>
  </user>
  <user username="user1" password="user1" />
</users>

<ssl enabled="false">
  <server-keystore path="$objectdb/ssl/server-kstore" password="pwd" />
  <client-truststore path="$objectdb/ssl/client-tstore" password="pwd" />
</ssl>

</objectdb>

another point: we see a thread that we did not see before:

"ODB-StoreHandler-8014" #8014 daemon prio=5 os_prio=0 tid=0x0000000051c05800 nid=0xc28 waiting for monitor entry [0x000000006b35e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.objectdb.o.LFL.UB(LFL.java:1098)
        - waiting to lock <0x00000002022346a8> (a com.objectdb.o.LFL)
        at com.objectdb.o.PAG.au(PAG.java:928)
        at com.objectdb.o.PGC.C(PGC.java:281)
        - locked <0x00000002029d8d18> (a java.lang.Object)
        at com.objectdb.o.SNP.G(SNP.java:436)
        at com.objectdb.o.MST.aZ(MST.java:510)
        at com.objectdb.o.MST.a0(MST.java:605)
        at com.objectdb.o.MST.Vm(MST.java:565)
        at com.objectdb.o.PLN.Vm(PLN.java:517)
        at com.objectdb.o.TAI.A(TAI.java:201)
        at com.objectdb.o.TAI.UI(TAI.java:134)
        at com.objectdb.o.TQI.UI(TQI.java:54)
        at com.objectdb.o.TQI.UI(TQI.java:54)
        at com.objectdb.o.MQI.VM(MQI.java:140)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.GQI.UI(GQI.java:148)
        at com.objectdb.o.PRG.ag(PRG.java:687)
        at com.objectdb.o.PRG.af(PRG.java:555)
        at com.objectdb.o.QRM.Vo(QRM.java:286)
        at com.objectdb.o.MST.Vo(MST.java:988)
        at com.objectdb.o.STC.s(STC.java:464)
        at com.objectdb.o.SHN.aj(SHN.java:489)
        at com.objectdb.o.SHN.K(SHN.java:155)
        at com.objectdb.o.HND.run(HND.java:133)
        at java.lang.Thread.run(Unknown Source)

   Locked ownable synchronizers:
        - None

Increasing the cache may help, so you may want to try it.

In addition, we just released a new build (2.7.1_01) that supports concurrent reading from the database file.

To enable the new option you have to set an environment variable before accessing ObjectDB:

    System.setProperty("objectdb.temp.concurrent-file-read", "true");

(or using the -D JVM argument).

It is unclear if this could improve performance of your application but you may want to try it (but be careful before integrating the new build into production, it passed our tests, but please report any side effect, if any).

we did integrate it into our pilot system and feedback results

after pilot testing we moved it to the productive environment and the situation is much better

Good news, thank you for the update.

This will probably become the default behaviour in future versions.

we have no again a similar situation where a lot of threads that are just doing a pure select query are waiting for locks (seems to be these are other locks than before):

java.lang.Thread.State: BLOCKED (on object monitor)
        at com.objectdb.o.PGC.C(PGC.java:254)
        - waiting to lock <0x00000003f9e86518> (a java.lang.Object)
        at com.objectdb.o.SNP.G(SNP.java:436)
        at com.objectdb.o.MST.a0(MST.java:510)
        at com.objectdb.o.MST.a1(MST.java:605)
        at com.objectdb.o.MST.U7(MST.java:565)
        at com.objectdb.o.PLN.U7(PLN.java:517)
        at com.objectdb.o.TAI.A(TAI.java:201)
        at com.objectdb.o.TAI.UI(TAI.java:134)
        at com.objectdb.o.TQI.UI(TQI.java:54)
        at com.objectdb.o.MQI.VM(MQI.java:140)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.MQI.VM(MQI.java:120)
        at com.objectdb.o.GQI.UI(GQI.java:148)
        at com.objectdb.o.SQI.UI(SQI.java:108)
        at com.objectdb.o.PRG.ag(PRG.java:687)
        at com.objectdb.o.PRG.af(PRG.java:555)
        at com.objectdb.o.QRM.U9(QRM.java:286)
        at com.objectdb.o.MST.U9(MST.java:988)
        at com.objectdb.o.WRA.U9(WRA.java:311)
        at com.objectdb.o.WSM.U9(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:719)
        - locked <0x00000007a49ae6a0> (a com.objectdb.jdo.PMImpl)


and:


java.lang.Thread.State: BLOCKED (on object monitor)
        at com.objectdb.o.SFL.ad(SFL.java:846)
        - waiting to lock <0x00000003f9a27b50> (a com.objectdb.o.MST)
        at com.objectdb.o.MST.Vd(MST.java:1891)
        at com.objectdb.o.MST.aZ(MST.java:479)
        at com.objectdb.o.MST.U6(MST.java:442)
        at com.objectdb.o.INR.h(INR.java:127)
        at com.objectdb.o.REG.U(REG.java:884)
        at com.objectdb.o.VAR.aA(VAR.java:826)
        at com.objectdb.o.XQI.VM(XQI.java:71)
        at com.objectdb.o.TQI.VM(TQI.java:69)
        at com.objectdb.o.MQI.VM(MQI.java:145)
        at com.objectdb.o.SQI.UI(SQI.java:119)
        at com.objectdb.o.PRG.ag(PRG.java:687)
        at com.objectdb.o.PRG.af(PRG.java:555)
        at com.objectdb.o.QRM.U9(QRM.java:286)
        at com.objectdb.o.MST.U9(MST.java:988)
        at com.objectdb.o.WRA.U9(WRA.java:311)
        at com.objectdb.o.WSM.U9(WSM.java:115)
        at com.objectdb.o.QRR.g(QRR.java:247)
        at com.objectdb.o.QRR.f(QRR.java:153)
        at com.objectdb.jpa.JpaQuery.getResultList(JpaQuery.java:719)
        - locked <0x00000007a44d5e20> (a com.objectdb.jdo.PMImpl)


and

java.lang.Thread.State: BLOCKED (on object monitor)
        at com.objectdb.o.PGC.C(PGC.java:276)
        - waiting to lock <0x00000003f9a33fe0> (a com.objectdb.o.PGC)
        at com.objectdb.o.SNP.G(SNP.java:436)
        at com.objectdb.o.RTT.l(RTT.java:127)
        at com.objectdb.o.RST.l(RST.java:24)
        at com.objectdb.o.TSK.i(TSK.java:145)
        at com.objectdb.o.TSK.f(TSK.java:95)
        at com.objectdb.o.MST.a1(MST.java:609)
        at com.objectdb.o.MST.U7(MST.java:565)
        at com.objectdb.o.WRA.U7(WRA.java:279)
        at com.objectdb.o.LDR.G(LDR.java:583)
        at com.objectdb.o.LDR.F(LDR.java:473)
        at com.objectdb.o.OBC.U2(OBC.java:1102)
        at com.objectdb.o.ENT.d(ENT.java:1182)
        at com.objectdb.o.ENT.extractCollection(ENT.java:1555)
        - locked <0x000000068db1c1f8> (a com.objectdb.jdo.PMImpl)

These stack traces show normal waiting for short time locks.

Maybe several full thread dumps can show a repeating pattern of a specific activity that holds such locks more than expected (the stack traces above only show waiting for locks rather than holding locks).