Issue #2299: Freeze during save

Type: BugVersion: 2.7.4_06Priority: CriticalStatus: ActiveReplies: 16
#1

During an write to an embedded database, objectdb gets stuck.  It won't progress from this point, even after a day of waiting. I include a stack trace from jvisualvm:

        at java.lang.System.identityHashCode(Native Method)
        at com.objectdb.o.IHS$f.<init>(IHS.java:195)
        at com.objectdb.o.IHS.q(IHS.java:58)
        at com.objectdb.o.EPR.Z4(EPR.java:98)
        at com.objectdb.o.UML.u(UML.java:587)
        at com.objectdb.o.MMM.K(MMM.java:1059)
        at com.objectdb.o.UTY.visitRefs(UTY.java:1349)
        at com.objectdb.o.TVS.e(TVS.java:170)
        at com.objectdb.o.TVS.cascade(TVS.java:157)
        at com.objectdb.o.OBM.aO(OBM.java:283)
        at com.objectdb.jdo.PMImpl.makePersistent(PMImpl.java:241)
        - locked <13f2027> (a com.spiffymap.naviupdate.model.Repository)
        - locked <5e745b> (a com.objectdb.jdo.PMImpl)
#2

Could you please post a full thread dump (with all threads). If there is a deadlock it should show it.

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#3

If there is no deadlock, it could be (according to the stack trace) an issue with cascading a persist operation. But more information is needed in order to find out the cause. Currently there is no similar open issue. During cascading objects are tracked and every object is handled only once to avoid an endless loop.

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#4

Here is the full thread dump:


2018-04-29 22:42:40
Full thread dump Java HotSpot(TM) Client VM (25.151-b12 mixed mode):

"RMI TCP Connection(2)-127.0.0.1" - Thread t@75
   java.lang.Thread.State: RUNNABLE
        at sun.management.ThreadImpl.dumpThreads0(Native Method)
        at sun.management.ThreadImpl.dumpAllThreads(ThreadImpl.java:454)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at sun.reflect.misc.Trampoline.invoke(MethodUtil.java:71)
        at sun.reflect.GeneratedMethodAccessor12.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at sun.reflect.misc.MethodUtil.invoke(MethodUtil.java:275)
        at com.sun.jmx.mbeanserver.ConvertingMethod.invokeWithOpenReturn(ConvertingMethod.java:193)
        at com.sun.jmx.mbeanserver.ConvertingMethod.invokeWithOpenReturn(ConvertingMethod.java:175)
        at com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(MXBeanIntrospector.java:117)
        at com.sun.jmx.mbeanserver.MXBeanIntrospector.invokeM2(MXBeanIntrospector.java:54)
        at com.sun.jmx.mbeanserver.MBeanIntrospector.invokeM(MBeanIntrospector.java:237)
        at com.sun.jmx.mbeanserver.PerInterface.invoke(PerInterface.java:138)
        at com.sun.jmx.mbeanserver.MBeanSupport.invoke(MBeanSupport.java:252)
        at javax.management.StandardMBean.invoke(StandardMBean.java:405)
        at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.invoke(DefaultMBeanServerInterceptor.java:819)
        at com.sun.jmx.mbeanserver.JmxMBeanServer.invoke(JmxMBeanServer.java:801)
        at javax.management.remote.rmi.RMIConnectionImpl.doOperation(RMIConnectionImpl.java:1468)
        at javax.management.remote.rmi.RMIConnectionImpl.access$300(RMIConnectionImpl.java:76)
        at javax.management.remote.rmi.RMIConnectionImpl$PrivilegedOperation.run(RMIConnectionImpl.java:1309)
        at javax.management.remote.rmi.RMIConnectionImpl.doPrivilegedOperation(RMIConnectionImpl.java:1401)
        at javax.management.remote.rmi.RMIConnectionImpl.invoke(RMIConnectionImpl.java:829)
        at sun.reflect.GeneratedMethodAccessor47.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357)
        at sun.rmi.transport.Transport$1.run(Transport.java:200)
        at sun.rmi.transport.Transport$1.run(Transport.java:197)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.Transport.serviceCall(Transport.java:196)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:568)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$62/4030619.run(Unknown Source)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - locked <ff9a15> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"JMX server connection timeout 74" - Thread t@74
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <51160f> (a [I)
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Connection(1)-127.0.0.1" - Thread t@73
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <21e2fb> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read(FilterInputStream.java:83)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:550)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$62/4030619.run(Unknown Source)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - locked <386c62> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"Timer-36" - Thread t@68
   java.lang.Thread.State: RUNNABLE
        at java.lang.System.identityHashCode(Native Method)
        at com.objectdb.o.IHS$f.<init>(IHS.java:195)
        at com.objectdb.o.IHS.q(IHS.java:58)
        at com.objectdb.o.EPR.Z4(EPR.java:98)
        at com.objectdb.o.UML.u(UML.java:587)
        at com.objectdb.o.MMM.K(MMM.java:1059)
        at com.objectdb.o.UTY.visitRefs(UTY.java:1349)
        at com.objectdb.o.TVS.e(TVS.java:170)
        at com.objectdb.o.TVS.cascade(TVS.java:157)
        at com.objectdb.o.OBM.aO(OBM.java:283)
        at com.objectdb.jdo.PMImpl.makePersistent(PMImpl.java:241)
        - locked <13f2027> (a com.spiffymap.naviupdate.model.Repository)
        - locked <5e745b> (a com.objectdb.jdo.PMImpl)
        at com.spiffymap.naviupdate.dao.repository.RepositoryJdoDao.lambda$save$2(RepositoryJdoDao.java:97)
        at com.spiffymap.naviupdate.dao.repository.RepositoryJdoDao$$Lambda$60/10789156.run(Unknown Source)
        at com.spiffymap.store.dao.TransactionalCode.run(TransactionalCode.java:90)
        at com.spiffymap.store.jdo.JdoDaoBase.runInTransaction(JdoDaoBase.java:950)
        at com.spiffymap.store.jdo.JdoDaoBase.runInTransaction(JdoDaoBase.java:888)
        at com.spiffymap.naviupdate.dao.repository.RepositoryJdoDao.save(RepositoryJdoDao.java:95)
        at com.spiffymap.naviupdate.io.RepositoryReader.readRepositoryAndStoreMetadata(RepositoryReader.java:660)
        at com.spiffymap.naviupdate.io.UpdateManager.indexNewData(UpdateManager.java:110)
        at com.spiffymap.naviupdate.services.UpdatesService.doUpdating(UpdatesService.java:408)
        at com.spiffymap.naviupdate.scheduling.Scheduler.doUpdating(Scheduler.java:244)
        at com.spiffymap.naviupdate.scheduling.Scheduler.doServerDataCheck(Scheduler.java:326)
        at com.spiffymap.naviupdate.scheduling.Scheduler$$Lambda$61/24014177.acceptName(Unknown Source)
        at com.spiffymap.naviupdate.scheduling.Scheduler$1.run(Scheduler.java:409)
        at java.util.TimerThread.mainLoop(Timer.java:555)
        at java.util.TimerThread.run(Timer.java:505)

   Locked ownable synchronizers:
        - None

"DestroyJavaVM" - Thread t@29
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Timer-1" - Thread t@27
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <1e5f25f> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:552)
        at java.util.TimerThread.run(Timer.java:505)

   Locked ownable synchronizers:
        - None

"org.eclipse.jetty.util.RolloverFileOutputStream" - Thread t@25
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <1a47568> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:552)
        at java.util.TimerThread.run(Timer.java:505)

   Locked ownable synchronizers:
        - None

"ODB-FileWriter" - Thread t@24
   java.lang.Thread.State: WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <4fc01a> (a com.objectdb.o.MST)
        at java.lang.Object.wait(Object.java:502)
        at com.objectdb.o.DFL.run(DFL.java:985)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"JMX client heartbeat 2" - Thread t@22
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Thread.sleep(Native Method)
        at com.sun.jmx.remote.internal.ClientCommunicatorAdmin$Checker.run(ClientCommunicatorAdmin.java:175)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"GC Daemon" - Thread t@21
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <f44df2> (a sun.misc.GC$LatencyLock)
        at sun.misc.GC$Daemon.run(GC.java:117)

   Locked ownable synchronizers:
        - None

"RMI RenewClean-[127.0.0.1:49217]" - Thread t@20
   java.lang.Thread.State: TIMED_WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <33979> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run(DGCClient.java:563)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI Scheduler(0)" - Thread t@19
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <181ae4> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Scheduler-19112467" - Thread t@18
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <3d5ead> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-17" - Thread t@17
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <4a0e85> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:565)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:628)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-16" - Thread t@16
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <4a0e85> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:565)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:628)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-15" - Thread t@15
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <4a0e85> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:565)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:628)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-14" - Thread t@14
   java.lang.Thread.State: TIMED_WAITING
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for <4a0e85> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at org.eclipse.jetty.util.BlockingArrayQueue.poll(BlockingArrayQueue.java:392)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.idleJobPoll(QueuedThreadPool.java:565)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.access$800(QueuedThreadPool.java:50)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:628)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-13-acceptor-0@1eeb4fb-ServerConnector@1295836{SSL,[ssl, http/1.1]}{0.0.0.0:3443}" - Thread t@13
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
        - locked <9c26eb> (a java.lang.Object)
        at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:352)
        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:603)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:673)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:591)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-12" - Thread t@12
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <6275e9> (a sun.nio.ch.Util$3)
        - locked <1eb7324> (a java.util.Collections$UnmodifiableSet)
        - locked <1bb48e6> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:234)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:187)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:211)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:126)
        at org.eclipse.jetty.io.ManagedSelector$$Lambda$32/31111960.run(Unknown Source)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:673)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:591)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-11" - Thread t@11
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
        at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
        at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
        - locked <8b8d44> (a sun.nio.ch.Util$3)
        - locked <1057ec1> (a java.util.Collections$UnmodifiableSet)
        - locked <1c35496> (a sun.nio.ch.EPollSelectorImpl)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:234)
        at org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:187)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:211)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:126)
        at org.eclipse.jetty.io.ManagedSelector$$Lambda$32/31111960.run(Unknown Source)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:673)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:591)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"qtp4081552-10-acceptor-0@b30b3b-ServerConnector@74f95d{HTTP/1.1,[http/1.1]}{0.0.0.0:3480}" - Thread t@10
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
        at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
        - locked <64cdb0> (a java.lang.Object)
        at org.eclipse.jetty.server.ServerConnector.accept(ServerConnector.java:352)
        at org.eclipse.jetty.server.AbstractConnector$Acceptor.run(AbstractConnector.java:603)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:673)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:591)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-0" - Thread t@9
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
        at java.net.ServerSocket.implAccept(ServerSocket.java:545)
        at java.net.ServerSocket.accept(ServerSocket.java:513)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:400)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:372)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-9999" - Thread t@8
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
        at java.net.ServerSocket.implAccept(ServerSocket.java:545)
        at java.net.ServerSocket.accept(ServerSocket.java:513)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:400)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:372)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" - Thread t@4
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Finalizer" - Thread t@3
   java.lang.Thread.State: WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <1553c84> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

   Locked ownable synchronizers:
        - None

"Reference Handler" - Thread t@2
   java.lang.Thread.State: WAITING
        at java.lang.Object.wait(Native Method)
        - waiting on <180d830> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
        - None
#5

Thanks. It doesn't look as a deadlock. Maybe it is an endless loop as suggested in #2 above.

More information is needed. Do you have a way to reproduce the issue or maybe enable remote debugging?

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#6

I can reproduce the problem with remote debugging, but it will take many hours.  I will post when it is ready.

#7

I have the application in the 'frozen' state, and I am connected to it via a remote debugger.  What would you like to see?

#8

Here is the stack trace of #1 deobfuscated:

at java.lang.System.identityHashCode(Native Method)
        at com.objectdb.o.IHS$f.<init>(OIdentityHashSet.java:195)
        at com.objectdb.common.data.OIdentityHashSet.q(OIdentityHashSet.java:58)
        at com.objectdb.pc.oper.EntityPersister.perform(EntityPersister.java:98)
        at com.objectdb.type.user.UserMemberList.visitRefs(UserMemberList.java:587)
        at com.objectdb.type.user.MemberManager.visitRefs(MemberManager.java:1059)
        at com.objectdb.type.user.UserType.visitRefs(UserType.java:1349)
        at com.objectdb.type.misc.TypeVisitor.visitReferenced(TypeVisitor.java:170)
        at com.objectdb.type.misc.TypeVisitor.cascade(TypeVisitor.java:157)
        at com.objectdb.pc.ObjectManager.persistEntity(ObjectManager.java:283)
        at com.objectdb.jdo.PMImpl.makePersistent(PMImpl.java:241)
        - locked <13f2027> (a com.spiffymap.naviupdate.model.Repository)

During makePersistent an attempt to cascade the operation to other objects never returns.

The cascade method contains a loop that using a stack visits every object that is reachable by cascading persist. Could you please check the objects in that loop (see local variables)? What is their type? Are there recurring objects? What is the size of the stack (an ALS instance)?

 

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#9

I have found recurring objects.  The stack is not large (26 stack frames).  Is there a way I can put in a trace of cascading persistence?  

I'm unable to proceed right now, as trying to run the Activator results in a 

Oops!

500 - Internal Server Error 

(I have managed to get around this with new activation codes).

#10

I have modified my object model to avoid the circular reference I found.  I will report back if this fixes the issue.

#11

Any further information about this issue may help:

  1. Are you using JPA or JDO?
  2. Can you describe the type of objects (entity objects, embedded objects, collections) in such a loop?
  3. Are inverse (mapped by) relationships included?
  4. What is the state of the objects in the loop (new, deleted, etc.)

Thanks

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#12

I'm using JDO, the objects are all entities.  The structure is new, and it's a tree.  The loops consisted of references to the root of the tree.  

I have managed to code around the problem, by removing the references to the tree root so there were no long loops.  Just an idea - what I would find helpful is some form of logging of the making persistent of objects, I can see what objectdb is up to when makePersistent takes time.

#13
Please confirm that you changed the default ObjectDB configuration to on-persist="true".

An attempt to reproduce the issue with the following test case failed (i.e. no freeze):

import java.util.*;

import javax.jdo.*;
import javax.jdo.annotations.*;
import javax.persistence.*;

public class I2299 {

    public static void main(String[] args) {
        PersistenceManagerFactory pmf =
            JDOHelper.getPersistenceManagerFactory("objectdb:2299.tmp;drop");
        PersistenceManager pm = pmf.getPersistenceManager();

        pm.currentTransaction().begin();
        MyNode root = new MyNode(null);
        MyNode child = new MyNode(root);
        MyNode grandchild = new MyNode(child);

        pm.makePersistent(root);
        pm.makePersistent(child);
        pm.makePersistent(grandchild);

        pm.currentTransaction().commit();

        pm.close();
        pmf.close();
    }

    @PersistenceCapable
    public static class MyNode {
       
        @ManyToOne(cascade=CascadeType.PERSIST)
        MyNode parent;

        @OneToMany(cascade=CascadeType.PERSIST)
        List<MyNode> children = new ArrayList();
       
        MyNode(MyNode parent) {
            if (parent != null) {
                parent.children.add(this);
                this.parent = parent;
            }           
        }
    }
}

Do you have any idea how to change this test case to reproduce the exception?

Debug logging was added in version 2.7.5 in order to collect more information.

Could you please run your test case with
        <logger name="entity.persist.cascade" level="debug" />
and post the relevant log lines?

Thanks.
ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#14

Sorry for the delay - it takes time to reproduce the issue.  I have re-introduced the reference loops into my data model, then ran my code with the cascading persistence logging, and I get around 54,000 entries in the log and then the application freezes.  If it helps I can send the log file and the sources for the data model.

#15

We appreciate your help with this issue. If you could send the log file and the data model source it may help. Thank you.

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)
#16
#17

Thank you for this report. Unfortunately we cannot reproduce it yet. We may have to keep it open until a test case that demonstrates it becomes available. Because you already managed to solve the issue in your case it may be less important for you now so investing more time by you on this issue may not be justified.

Something in the log file that you sent is strange: The log entries are mixed and not ordered by age, even though writing to the log file is synchronized by ObjectDB. Are you using special concurrency, e.g. by multiple JVM instances of class loaders? Maybe it could be related to the issue.

ObjectDB Support
ObjectDB - Fast Object Database for Java (JPA/JDO)

Post Reply

To post a reply and/or subscribe to update notifications - please login