Starting demo app takes ages (10-12min on every "Run OSGi" startup)

Development IDE & Build
1
  • Platform information:
    • Hardware: i7 64 bit
    • OS: Arch linux
    • Java Runtime Environment: openjdk version “11.0.11” 2021-04-20
    • openHAB version: Latest Github main/master checkouts

I have just started from scratch again (after my current IDE had random resolving errors).

What I did:

  • Cleaned ~/.m2
  • Created an new ~.p2/pool
  • Fresh install via latest Eclipse Installer using Eclipse 2021-03
  • Checked openHAB Development and addon development

Result is sometimes an OutOfMemoryException, but I have only seen it once so far:

Exception in thread "Equinox resolver thread - Equinox Container: 77da5b7f-236d-4fa6-adc8-8a8105e24cba" Exception in thread "pool-1-thread-1" java.lang.OutOfMemoryError: Java heap space
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.addWaiter(AbstractQueuedSynchronizer.java:651)
	at java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1240)
	at java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:267)
	at java.base/java.util.concurrent.ThreadPoolExecutor.processWorkerExit(ThreadPoolExecutor.java:986)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
java.lang.OutOfMemoryError: Java heap space
____________________________
Welcome to Apache Felix Gogo

g! 15:37:54.506 [INFO ] [org.openhab.ui.internal.UIService   ] - Started UI on port 8080

And until the “Started UI” it takes around 10 minutes or so.

If I kill the Java process to get a thread dump ater around 4-5mins, it looks like the felix resolver is running amok…

2021-05-08 17:55:10
Full thread dump OpenJDK 64-Bit Server VM (11.0.11+9 mixed mode):

Threads class SMR info:
_java_thread_list=0x00007f61e419edd0, length=21, elements={
0x00007f6258018000, 0x00007f62581e6800, 0x00007f62581ea800, 0x00007f62581ff800,
0x00007f6258201800, 0x00007f6258203800, 0x00007f6258205800, 0x00007f6258207800,
0x00007f6258295800, 0x00007f62582d2000, 0x00007f62582d6000, 0x00007f61f4001800,
0x00007f6258404800, 0x00007f625852d000, 0x00007f61c8002800, 0x00007f6258524800,
0x00007f6258525800, 0x00007f625853a000, 0x00007f6258566800, 0x00007f6258573000,
0x00007f625855c000
}

"main" #1 prio=5 os_prio=0 cpu=66649.16ms elapsed=224.95s tid=0x00007f6258018000 nid=0x17cf7 runnable  [0x00007f625d7ab000]
   java.lang.Thread.State: RUNNABLE
	at org.apache.felix.resolver.util.OpenHashMap.get(OpenHashMap.java:484)
	at org.apache.felix.resolver.Candidates.getCandidates(Candidates.java:695)
	at org.apache.felix.resolver.ResolverImpl$ResolveSession.permutateIfNeeded(ResolverImpl.java:143)
	at org.apache.felix.resolver.ResolverImpl.checkPackageSpaceConsistency(ResolverImpl.java:1494)
	at org.apache.felix.resolver.ResolverImpl.checkPackageSpaceConsistency(ResolverImpl.java:1524)
	at org.apache.felix.resolver.ResolverImpl.checkConsistency(ResolverImpl.java:621)
	at org.apache.felix.resolver.ResolverImpl.findValidCandidates(ResolverImpl.java:574)
	at org.apache.felix.resolver.ResolverImpl.doResolve(ResolverImpl.java:437)
	at org.apache.felix.resolver.ResolverImpl.resolve(ResolverImpl.java:420)
	at org.apache.felix.resolver.ResolverImpl.resolve(ResolverImpl.java:374)
	at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisions(ModuleResolver.java:1126)
	at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:1080)
	at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:997)
	at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:170)
	at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:547)
	at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:502)
	at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:491)
	at org.eclipse.osgi.container.Module.start(Module.java:446)
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1845)
	at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1838)
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1779)
	at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1743)
	- locked <0x000000070a6bc438> (a java.lang.Object)
	at org.eclipse.osgi.container.SystemModule.startWorker(SystemModule.java:269)
	at org.eclipse.osgi.container.Module.doStart(Module.java:605)
	at org.eclipse.osgi.container.Module.start(Module.java:468)
	at org.eclipse.osgi.container.SystemModule.start(SystemModule.java:193)
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:440)
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:459)
	at org.eclipse.osgi.launch.Equinox.start(Equinox.java:139)
	at aQute.launcher.Launcher.activate(Launcher.java:566)
	at aQute.launcher.Launcher.launch(Launcher.java:404)
	at aQute.launcher.Launcher.run(Launcher.java:185)
	at aQute.launcher.Launcher.main(Launcher.java:161)
	at java.lang.invoke.LambdaForm$DMH/0x0000000800064c40.invokeStaticInit(java.base@11.0.11/LambdaForm$DMH)
	at java.lang.invoke.LambdaForm$MH/0x00000008000d0440.invoke(java.base@11.0.11/LambdaForm$MH)
	at java.lang.invoke.LambdaForm$MH/0x00000008000d0040.invoke_MT(java.base@11.0.11/LambdaForm$MH)
	at aQute.launcher.pre.EmbeddedLauncher.executeWithRunPath(EmbeddedLauncher.java:170)
	at aQute.launcher.pre.EmbeddedLauncher.findAndExecute(EmbeddedLauncher.java:135)
	at aQute.launcher.pre.EmbeddedLauncher.main(EmbeddedLauncher.java:52)

"Reference Handler" #2 daemon prio=10 os_prio=0 cpu=0.56ms elapsed=224.92s tid=0x00007f62581e6800 nid=0x17d00 waiting on condition  [0x00007f62312eb000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@11.0.11/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@11.0.11/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@11.0.11/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=0 cpu=0.39ms elapsed=224.92s tid=0x00007f62581ea800 nid=0x17d01 in Object.wait()  [0x00007f62311ea000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <0x000000070a564f80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x000000070a564f80> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@11.0.11/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 cpu=0.15ms elapsed=224.91s tid=0x00007f62581ff800 nid=0x17d02 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=0 cpu=0.05ms elapsed=224.91s tid=0x00007f6258201800 nid=0x17d03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=0 cpu=7711.35ms elapsed=224.91s tid=0x00007f6258203800 nid=0x17d04 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #8 daemon prio=9 os_prio=0 cpu=979.96ms elapsed=224.91s tid=0x00007f6258205800 nid=0x17d05 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #9 daemon prio=9 os_prio=0 cpu=0.10ms elapsed=224.91s tid=0x00007f6258207800 nid=0x17d06 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #10 daemon prio=8 os_prio=0 cpu=0.62ms elapsed=224.85s tid=0x00007f6258295800 nid=0x17d07 in Object.wait()  [0x00007f62308a7000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <0x000000070a565a18> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@11.0.11/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x000000070a565a18> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@11.0.11/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)
	at jdk.internal.misc.InnocuousThread.run(java.base@11.0.11/InnocuousThread.java:134)

"JDWP Transport Listener: dt_socket" #11 daemon prio=10 os_prio=0 cpu=21.59ms elapsed=224.82s tid=0x00007f62582d2000 nid=0x17d09 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Event Helper Thread" #12 daemon prio=10 os_prio=0 cpu=0.77ms elapsed=224.82s tid=0x00007f62582d6000 nid=0x17d0a runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"JDWP Command Reader" #13 daemon prio=10 os_prio=0 cpu=3.51ms elapsed=224.82s tid=0x00007f61f4001800 nid=0x17d0b runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"pool-1-thread-1" #14 prio=5 os_prio=0 cpu=19.32ms elapsed=224.31s tid=0x00007f6258404800 nid=0x17d11 runnable  [0x00007f61ebffe000]
   java.lang.Thread.State: RUNNABLE
	at java.lang.Thread.currentThread(java.base@11.0.11/Native Method)
	at java.util.concurrent.FutureTask.runAndReset(java.base@11.0.11/FutureTask.java:297)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(java.base@11.0.11/ScheduledThreadPoolExecutor.java:305)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1128)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Equinox resolver thread - Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #16 daemon prio=5 os_prio=0 cpu=17786.40ms elapsed=223.92s tid=0x00007f625852d000 nid=0x17d1a waiting on condition  [0x00007f61eb6f5000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x000000070a90c8d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.11/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.11/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.11/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Equinox resolver thread - Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #17 daemon prio=5 os_prio=0 cpu=17741.14ms elapsed=223.91s tid=0x00007f61c8002800 nid=0x17d1b waiting on condition  [0x00007f61eb5f4000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x000000070a90c8d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.11/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.11/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.11/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Equinox resolver thread - Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #18 daemon prio=5 os_prio=0 cpu=17731.77ms elapsed=223.91s tid=0x00007f6258524800 nid=0x17d1c waiting on condition  [0x00007f61eb4f3000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x000000070a90c8d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.11/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.11/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.11/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Equinox resolver thread - Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #19 daemon prio=5 os_prio=0 cpu=17935.46ms elapsed=223.90s tid=0x00007f6258525800 nid=0x17d1d waiting on condition  [0x00007f61eb3f2000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x000000070a90c8d0> (a java.util.concurrent.SynchronousQueue$TransferStack)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(java.base@11.0.11/SynchronousQueue.java:462)
	at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@11.0.11/SynchronousQueue.java:361)
	at java.util.concurrent.SynchronousQueue.poll(java.base@11.0.11/SynchronousQueue.java:937)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1053)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"Active Thread: Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #20 prio=5 os_prio=0 cpu=107.33ms elapsed=223.87s tid=0x00007f625853a000 nid=0x17d1e waiting on condition  [0x00007f61eb2f1000]
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@11.0.11/Native Method)
	- parking to wait for  <0x000000070a90df10> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.11/LockSupport.java:234)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.11/AbstractQueuedSynchronizer.java:2123)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:1182)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@11.0.11/ScheduledThreadPoolExecutor.java:899)
	at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@11.0.11/ThreadPoolExecutor.java:1054)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.11/ThreadPoolExecutor.java:1114)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.11/ThreadPoolExecutor.java:628)
	at java.lang.Thread.run(java.base@11.0.11/Thread.java:829)

"FrameworkWaiter" #22 prio=5 os_prio=0 cpu=0.34ms elapsed=223.79s tid=0x00007f6258566800 nid=0x17d1f in Object.wait()  [0x00007f61eb1f0000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <0x000000070a90e150> (a java.util.concurrent.atomic.AtomicReference)
	at org.eclipse.osgi.container.SystemModule.waitForStop(SystemModule.java:173)
	- waiting to re-lock in wait() <0x000000070a90e150> (a java.util.concurrent.atomic.AtomicReference)
	at org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle.waitForStop(EquinoxBundle.java:307)
	at org.eclipse.osgi.launch.Equinox.waitForStop(Equinox.java:217)
	at aQute.launcher.Launcher$1.run(Launcher.java:1040)

"Framework Event Dispatcher: Equinox Container: 0a40964d-291b-4bb7-8bd2-490e4010d5cc" #23 daemon prio=5 os_prio=0 cpu=3.93ms elapsed=223.76s tid=0x00007f6258573000 nid=0x17d20 in Object.wait()  [0x00007f61eb0ef000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <0x000000070a90e170> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at java.lang.Object.wait(java.base@11.0.11/Object.java:328)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- waiting to re-lock in wait() <0x000000070a90e170> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"Bundle File Closer" #24 daemon prio=5 os_prio=0 cpu=6.23ms elapsed=223.51s tid=0x00007f625855c000 nid=0x17d21 in Object.wait()  [0x00007f61eafee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(java.base@11.0.11/Native Method)
	- waiting on <0x000000070a90e2f0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at java.lang.Object.wait(java.base@11.0.11/Object.java:328)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
	- waiting to re-lock in wait() <0x000000070a90e2f0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

"VM Thread" os_prio=0 cpu=664.47ms elapsed=224.93s tid=0x00007f62581de000 nid=0x17cff runnable  

"GC Thread#0" os_prio=0 cpu=125517.43ms elapsed=224.95s tid=0x00007f625802f800 nid=0x17cfa runnable  

"GC Thread#1" os_prio=0 cpu=126599.17ms elapsed=224.25s tid=0x00007f6220001000 nid=0x17d12 runnable  

"GC Thread#2" os_prio=0 cpu=126704.42ms elapsed=224.25s tid=0x00007f6220002800 nid=0x17d13 runnable  

"GC Thread#3" os_prio=0 cpu=125943.58ms elapsed=224.25s tid=0x00007f6220004000 nid=0x17d14 runnable  

"G1 Main Marker" os_prio=0 cpu=3.92ms elapsed=224.95s tid=0x00007f625808c800 nid=0x17cfb runnable  

"G1 Conc#0" os_prio=0 cpu=46701.33ms elapsed=224.95s tid=0x00007f625808e000 nid=0x17cfc runnable  

"G1 Refine#0" os_prio=0 cpu=481.08ms elapsed=224.94s tid=0x00007f625817a000 nid=0x17cfd runnable  

"G1 Refine#1" os_prio=0 cpu=252.13ms elapsed=224.24s tid=0x00007f6228001000 nid=0x17d15 runnable  

"G1 Refine#2" os_prio=0 cpu=140.57ms elapsed=223.16s tid=0x00007f61d4001800 nid=0x17d22 runnable  

"G1 Refine#3" os_prio=0 cpu=102.05ms elapsed=223.16s tid=0x00007f61b8002000 nid=0x17d23 runnable  

"G1 Young RemSet Sampling" os_prio=0 cpu=42.84ms elapsed=224.94s tid=0x00007f625817b800 nid=0x17cfe runnable  
"VM Periodic Task Thread" os_prio=0 cpu=89.69ms elapsed=224.66s tid=0x00007f62582d8800 nid=0x17d0f waiting on condition  

JNI global refs: 50, weak refs: 27

Heap
 garbage-first heap   total 4026368K, used 3993969K [0x000000070a400000, 0x0000000800000000)
  region size 1024K, 1 young (1024K), 0 survivors (0K)
 Metaspace       used 15712K, capacity 15985K, committed 16384K, reserved 1064960K
  class space    used 1424K, capacity 1498K, committed 1536K, reserved 1048576K

Does anyone have an idea what is wrong?

2

this. openJDK is not recommended.

For sure your HW/OS/Java combo is uncommon thus probably untested.

maybe this.
Unclear what you did there and why. Usually one would install a package not build from sources.

3

So you recommend that I should use the Oracle java instead?

Hardware is a standard i7 based laptop with linux running on it. I dont know what should be that unusual about it…

I just followed Eclipse IDE | openHAB

So I dont know what you mean by “installed from source”… I did not compile anything myself if that is what you meant. Also the eclipse version 2021-03 is the latest stable in the official eclipse installer.

4

No, Stefan wants to setup a development environment, so absolutely ok…
@triller-telekom Please use Zulu 11…

5

Recommended java is Zulu, and there’s many Linux variants. Arch definitely is unusual.
And given you have issues, as such it’s a potential cause.

Well he should have told in the first place then.

6

He did :wink:

7

I just tried it with Oracle 16 and its the same issue: Takes forever to start.

I have to note that I never had such an issue before. And my IDE was running fine on Arch linux since years. I have started openHAB development 4 years ago and have used Arch linux ever since.

I will now try to install zulu, but I doubt that it will solve the issue. I am really wondering why the resolving of bundles takes so long durind startup.

There must be something else that is broken.

8

No Java higher or lower than 11 for openHAB 3 !!!

9

I had something like that in mind, i.e. Java 11. thats why I had the openjdk 11 initially and that worked fine in the last month.

However in the current main/master branches it doesnt work anymore!

I also tried zulu-16 and zulu-11 just now. Same result :frowning:

10

Edit: Last start with zulu 11 jdk took 12mins in the IDE for the demo app.

Since it didnt happen on older versions of openHAB and given the fact that it occurs with ALL jdk runtimes, I would now blame some dependency resolving between the bundles which is wrong.

Are you able to start the default demo app.bndrun without any changes to it on the latest main branch? How long does it take to start?

11

I tried to solve the problem, but now I am out of ideas. I am 99.99999% sure that there is a broken dependency or even a cycle somewhere in the bundle definitions.

For those who are able to successfully start the runtime from within their IDE: could you please try to setup a second instance with a separate bundle pool and see if it also works there?

What I now tried without any success:

  • Use a separate linux user with an EMPTY home, i.e. no caches, nothing and the recommended zulu 11 java
  • Update bndtools to 6.x-SNAPSHOT
  • Downgrade bndtools to 5.2
  • Install with an older Eclipse (2020-09) and bndtools 5.3
  • Install with an older Eclipse (2020-09) and downgrade bndtools to 5.2

Nothing worked! I CAN start the runtime, but it ALWAYS takes around 10-12minutes for a single startup where the CPU usage is on 100% until it has been started. The thread dump on what it is actually doing, see above.

So I am really curious if its only working for those of you who have some caches filled and for new users it will always fail like for me…

12

I haven’t tested setting up a new Eclipse for a while, but it does work for me.
Though I always customize Eclipse by giving it more memory by adding the following to eclipse.ini:

-Xms2g
-Xmx8g

Lower values probably also work, but since I have a lot of memory doing nothing, I rather put it to good use. :wink:

13

Thanks for your suggestion to allocate more memory for the JVM. However, the OOM Exception only occurred on the very first attempt for me, it runs “fine” with the defaults of -Xms512m and -Xmx2g.

And with “fine” I mean that it runs but it takes 10-12mins to even start, everytime I click the “Run OSGi” button.

It keeps resolving for 10-12mins (possibly runs into a timeout then) and then the runtime finally starts and the CPU usage goes back to almost idle.

Adding more memory doesnt change anything on those 10-12mins, it just uses more memory, thats all :frowning:

@wborn Could you please install a second version next to yours with a separate bundle pool to see if you run into my issue as well?

14

I created a fresh Ubuntu 21.04 VM with only 8GB of memory to simulate a more common PC. Then I also ran into your memory issues when launching the app. The reason is that there is no -Xmx VM parameter specified so then the JVM assigns x% of your total memory to the Java application. On my real PC that was 16GB while in the VM it was only 2GB.

According to VisualVM it takes a lot of memory to initially resolve/start all bundles. But after that it drops significantly:

startup
startup1159×676 78.2 KB

It will probably work for you as well if you add -Xmx8g in the JVM Arguments, that will add -runvm: -Xmx8g to the app.bndrun file. Maybe we can find a way to reduce this big amount of memory needed. :roll_eyes:

15

Thank you very much for your analysis. I think this is going into the right direction.

However, I am now at -Xmx10g and it uses that much memory, but it still takes 1.5mins so 90 seconds until the runtime starts…

Tested with bndtools 5.3 on latest 202103 Eclipse with zulu java-11.

So giving more ram to the app.bndrun startscrip certainly improves the situation, i.e. from 12mins down to 1.5, but still thats A LOT…

The runtime used to start within seconds, roughly anything below 10, I would say…

Edit: I am also wondering why bndtools needs to resolve on EVERY startup… I would think that clicking the “Resolve” button and saving the app.bndrun file would be sufficient for the next run, as everything is already resolved at that point.

Edit2: I found https://issues.apache.org/jira/browse/KARAF-6068 which looks as if this might be related. I don’t know if we have such a situation where a bundle exports packages of different versions though…

1 Like
16

Not that resolver. There’s another one, the Apache Felix Resolver which resolves bundles for the OSGi runtime.

But I seem to have already fixed it by rearranging the runbundles :slight_smile: :

new-startup
new-startup1092×687 67.1 KB

I added the fix as part of openhab/openhab-distro#1287.

You can also try it on the current main branch by removing all runbundles and reresolving them. Then move the pax-logging bundles to the top so they immediately apply the right loglevels.

17

Thank you both for elaborating this. Now it makes much more fun to debug code via Eclipse again.

:+1:

1 Like
18

I face the exact same issue on a newly fresh installed machine :

  • Platform information:
    • Hardware: i7 64 bit
    • OS: Ubuntu 22.10
    • Java Runtime Environment: oracle 17

Fresh install of the IDE (Eclipse 22.03) from Eclipse Installer.
Resolved the org.openhab.demo.app

Clicked on “Run OSGi” takes around 10 minutes, all cores (x8) at 100%

image

image
image710×85 14.8 KB

19

@glhopital see this:

Not a diagnosis or a solution , but a hint that may find you luckier

20

it looks like ti very much depends on which addons/bindings you add to the run configuration. The default was fine for me, but when I added the tr064 binding I face the out of memory error: