2576 words

locks on pure query activities

#1
2017-04-28 09:28

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



 

 

hgzwicker
hgzwicker's picture
Joined on 2014-04-09
User Post #26
#2
2017-05-01 20:38

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.
ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
support
support's picture
Joined on 2010-05-03
User Post #2,753
#3
2017-05-02 06:09
  • 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

 

 

 

hgzwicker
hgzwicker's picture
Joined on 2014-04-09
User Post #27
#4
2017-05-04 12:54

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).

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
support
support's picture
Joined on 2010-05-03
User Post #2,754
#5
2017-05-05 10:15

we did integrate it into our pilot system and feedback results

hgzwicker
hgzwicker's picture
Joined on 2014-04-09
User Post #28
#6
2017-05-10 16:12

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

hgzwicker
hgzwicker's picture
Joined on 2014-04-09
User Post #29
#7
2017-05-11 12:50

Good news, thank you for the update.

This will probably become the default behaviour in future versions.

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
support
support's picture
Joined on 2010-05-03
User Post #2,755
#8
2017-05-29 08:09

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)

 

 

hgzwicker
hgzwicker's picture
Joined on 2014-04-09
User Post #30
#9
2017-06-01 11:44

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).

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
support
support's picture
Joined on 2010-05-03
User Post #2,758

Post Reply

Please read carefully the posting instructions - before posting to the ObjectDB website.

  • You may have to disable pop up blocking in order to use the toolbar (e.g. in Chrome).
  • Use ctrl + right click to open the browser context menu in the editing area (e.g. for using a browser spell checker).
  • To insert formatted lines (e.g. Java code, stack trace) - select a style in the toolbar and then insert the text in the new created block.
  • Avoid overflow of published source code examples by breaking long lines.
  • You may mark in paragraph code words (e.g. class names) with the code style (can be applied by ctrl + D).
  • Long stack traces (> 50 lines) and complex source examples (> 100 lines) should be posted as attachments.
Attachments:
Maximum file size: 32 MB
Cancel