eclipse-equinox / equinox

equinox
Eclipse Public License 2.0
33 stars 65 forks source link

Startup Takes Forever #93

Closed merks closed 2 years ago

merks commented 2 years ago

I've noticed lately that when I update a 2022-06 installation to 2022-09 (M1) that startup takes seemly forever.

image

Here's what the threads are doing.

resolver-threads.txt

At this point, only the splash screen shows.

Here's a later version of the data inline:


2022-08-04 10:16:55
Full thread dump OpenJDK 64-Bit Server VM (17.0.1+12 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x000001f6b9442fb0, length=39, elements={
0x000001f6932780b0, 0x000001f6b3f1b220, 0x000001f6b3f1bf80, 0x000001f6b3f325b0,
0x000001f6b3f349f0, 0x000001f6b3f3f770, 0x000001f6b3f429a0, 0x000001f6b3f4e2a0,
0x000001f6b6df1b30, 0x000001f6b6dfa030, 0x000001f6b6eeba50, 0x000001f6b703a8f0,
0x000001f6b8afa2a0, 0x000001f6b8afa770, 0x000001f6b89d9040, 0x000001f6b935b0c0,
0x000001f6b8b0b440, 0x000001f6b87e6280, 0x000001f6b8b67480, 0x000001f6b89d4620,
0x000001f6b87d95c0, 0x000001f6b87d90f0, 0x000001f6b87da900, 0x000001f6b87dadd0,
0x000001f6b87d9f60, 0x000001f6b87db770, 0x000001f6b87d9a90, 0x000001f6b87dbc40,
0x000001f6b87d8750, 0x000001f6b87d8280, 0x000001f6b87d8c20, 0x000001f6bb22b8f0,
0x000001f6bb228da0, 0x000001f6bb22aa80, 0x000001f6bb229740, 0x000001f6bb22af50,
0x000001f6bb229c10, 0x000001f6bb22a0e0, 0x000001f6bb22bdc0
}

"main" #1 prio=5 os_prio=0 cpu=1671.88ms elapsed=1914.36s tid=0x000001f6932780b0 nid=0x8968 runnable  [0x000000125cf3e000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000072ded1c00> (a java.util.concurrent.Semaphore$NonfairSync)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(java.base@17.0.1/AbstractQueuedSynchronizer.java:717)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(java.base@17.0.1/AbstractQueuedSynchronizer.java:1074)
        at java.util.concurrent.Semaphore.tryAcquire(java.base@17.0.1/Semaphore.java:415)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.updateSplash(EclipseStarter.java:1191)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.setStartLevel(EclipseStarter.java:1146)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.startup(EclipseStarter.java:346)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:251)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@17.0.1/Native Method)
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@17.0.1/NativeMethodAccessorImpl.java:77)
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@17.0.1/DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(java.base@17.0.1/Method.java:568)
        at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
        at org.eclipse.equinox.launcher.Main.basicRun(Main.java:596)
        at org.eclipse.equinox.launcher.Main.run(Main.java:1467)

   Locked ownable synchronizers:
        - None

"Reference Handler" #2 daemon prio=10 os_prio=2 cpu=0.00ms elapsed=1914.35s tid=0x000001f6b3f1b220 nid=0x838c waiting on condition  [0x000000125dcff000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.ref.Reference.waitForReferencePendingList(java.base@17.0.1/Native Method)
        at java.lang.ref.Reference.processPendingReferences(java.base@17.0.1/Reference.java:253)
        at java.lang.ref.Reference$ReferenceHandler.run(java.base@17.0.1/Reference.java:215)

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=1 cpu=0.00ms elapsed=1914.35s tid=0x000001f6b3f1bf80 nid=0x9874 in Object.wait()  [0x000000125ddff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <0x00000007003339d8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.1/ReferenceQueue.java:155)
        - locked <0x00000007003339d8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.1/ReferenceQueue.java:176)
        at java.lang.ref.Finalizer$FinalizerThread.run(java.base@17.0.1/Finalizer.java:172)

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 cpu=0.00ms elapsed=1914.34s tid=0x000001f6b3f325b0 nid=0x78a8 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Attach Listener" #5 daemon prio=5 os_prio=2 cpu=156.25ms elapsed=1914.34s tid=0x000001f6b3f349f0 nid=0x328 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Service Thread" #6 daemon prio=9 os_prio=0 cpu=15.62ms elapsed=1914.34s tid=0x000001f6b3f3f770 nid=0x5378 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Monitor Deflation Thread" #7 daemon prio=9 os_prio=0 cpu=15.62ms elapsed=1914.34s tid=0x000001f6b3f429a0 nid=0x3a54 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #8 daemon prio=9 os_prio=2 cpu=6468.75ms elapsed=1914.34s tid=0x000001f6b3f4e2a0 nid=0x9c0c waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
        - None

"C1 CompilerThread0" #16 daemon prio=9 os_prio=2 cpu=671.88ms elapsed=1914.34s tid=0x000001f6b6df1b30 nid=0x81d8 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
        - None

"Sweeper thread" #20 daemon prio=9 os_prio=2 cpu=93.75ms elapsed=1914.34s tid=0x000001f6b6dfa030 nid=0x6ea4 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Common-Cleaner" #21 daemon prio=8 os_prio=1 cpu=0.00ms elapsed=1914.33s tid=0x000001f6b6eeba50 nid=0x34f4 in Object.wait()  [0x000000125e5fe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.1/ReferenceQueue.java:155)
        - locked <0x000000070039b358> (a java.lang.ref.ReferenceQueue$Lock)
        at jdk.internal.ref.CleanerImpl.run(java.base@17.0.1/CleanerImpl.java:140)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)
        at jdk.internal.misc.InnocuousThread.run(java.base@17.0.1/InnocuousThread.java:162)

   Locked ownable synchronizers:
        - None

"Notification Thread" #22 daemon prio=9 os_prio=0 cpu=0.00ms elapsed=1914.32s tid=0x000001f6b703a8f0 nid=0x9220 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #24 daemon prio=5 os_prio=0 cpu=342906.25ms elapsed=1914.00s tid=0x000001f6b8afa2a0 nid=0x6390 runnable  [0x000000125fcfd000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap$HashIterator.nextNode(java.base@17.0.1/HashMap.java:1601)
        at java.util.HashMap$KeyIterator.next(java.base@17.0.1/HashMap.java:1620)
        at java.util.AbstractCollection.containsAll(java.base@17.0.1/AbstractCollection.java:308)
        at java.util.AbstractSet.equals(java.base@17.0.1/AbstractSet.java:95)
        at org.apache.felix.resolver.util.ArrayMap.getOrCompute(ArrayMap.java:73)
        at org.apache.felix.resolver.ResolverImpl.addUsedBlames(ResolverImpl.java:1308)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1115)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:868)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #25 daemon prio=5 os_prio=0 cpu=345828.12ms elapsed=1914.00s tid=0x000001f6b8afa770 nid=0x19cc runnable  [0x000000125fdfe000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.util.OpenHashMap.get(OpenHashMap.java:484)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:817)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #26 daemon prio=5 os_prio=0 cpu=340640.62ms elapsed=1914.00s tid=0x000001f6b89d9040 nid=0x984c runnable  [0x000000125feff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #27 daemon prio=5 os_prio=0 cpu=342640.62ms elapsed=1914.00s tid=0x000001f6b935b0c0 nid=0x8db0 runnable  [0x000000125fffe000]
   java.lang.Thread.State: RUNNABLE
        at java.util.concurrent.ConcurrentHashMap.get(java.base@17.0.1/ConcurrentHashMap.java:946)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:816)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #28 daemon prio=5 os_prio=0 cpu=342015.62ms elapsed=1914.00s tid=0x000001f6b8b0b440 nid=0xcd4 runnable  [0x00000012600fd000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1096)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:868)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #29 daemon prio=5 os_prio=0 cpu=343265.62ms elapsed=1914.00s tid=0x000001f6b87e6280 nid=0x6e9c runnable  [0x00000012601fe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Active Thread: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #30 prio=5 os_prio=0 cpu=296.88ms elapsed=1913.98s tid=0x000001f6b8b67480 nid=0x8708 waiting on condition  [0x00000012602fe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x00000007008c2f58> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@17.0.1/AbstractQueuedSynchronizer.java:1672)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.1/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.1/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1062)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Framework Event Dispatcher: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #32 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=1913.94s tid=0x000001f6b89d4620 nid=0x4580 in Object.wait()  [0x00000012603ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.Object.wait(java.base@17.0.1/Object.java:338)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
        - locked <0x00000007008c30b0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

   Locked ownable synchronizers:
        - None

"Refresh Thread: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #33 daemon prio=5 os_prio=0 cpu=16296.88ms elapsed=1913.94s tid=0x000001f6b87d95c0 nid=0x8220 in Object.wait()  [0x00000012604ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.Object.wait(java.base@17.0.1/Object.java:338)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
        - locked <0x00000007008c32a8> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #34 daemon prio=5 os_prio=0 cpu=343265.62ms elapsed=1913.86s tid=0x000001f6b87d90f0 nid=0x78f8 waiting on condition  [0x00000012607fe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #35 daemon prio=5 os_prio=0 cpu=343156.25ms elapsed=1913.86s tid=0x000001f6b87da900 nid=0x9f2c waiting on condition  [0x00000012608ff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #36 daemon prio=5 os_prio=0 cpu=345109.38ms elapsed=1913.86s tid=0x000001f6b87dadd0 nid=0x9e4c runnable  [0x00000012609fe000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap.put(java.base@17.0.1/HashMap.java:610)
        at java.util.HashSet.add(java.base@17.0.1/HashSet.java:221)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1035)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:887)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #37 daemon prio=5 os_prio=0 cpu=343312.50ms elapsed=1913.86s tid=0x000001f6b87d9f60 nid=0x2e50 runnable  [0x0000001260afe000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap$HashIterator.nextNode(java.base@17.0.1/HashMap.java:1601)
        at java.util.HashMap$KeyIterator.next(java.base@17.0.1/HashMap.java:1620)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1040)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:887)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #38 daemon prio=5 os_prio=0 cpu=341859.38ms elapsed=1913.86s tid=0x000001f6b87db770 nid=0x9140 waiting on condition  [0x0000001260bfe000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #39 daemon prio=5 os_prio=0 cpu=342281.25ms elapsed=1913.86s tid=0x000001f6b87d9a90 nid=0x2b74 runnable  [0x0000001260cfe000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:837)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #40 daemon prio=5 os_prio=0 cpu=342015.62ms elapsed=1913.86s tid=0x000001f6b87dbc40 nid=0x71c waiting on condition  [0x0000001260dff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #41 daemon prio=5 os_prio=0 cpu=344078.12ms elapsed=1913.86s tid=0x000001f6b87d8750 nid=0x4518 runnable  [0x0000001260efd000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.util.OpenHashMap.getOrCompute(OpenHashMap.java:340)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1096)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1118)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:887)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #42 daemon prio=5 os_prio=0 cpu=341625.00ms elapsed=1913.86s tid=0x000001f6b87d8280 nid=0x545c runnable  [0x0000001260ffe000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap.putVal(java.base@17.0.1/HashMap.java:627)
        at java.util.HashMap.put(java.base@17.0.1/HashMap.java:610)
        at java.util.HashSet.add(java.base@17.0.1/HashSet.java:221)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1035)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:849)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

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

"Equinox resolver thread - Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #43 daemon prio=5 os_prio=0 cpu=342375.00ms elapsed=1913.86s tid=0x000001f6b87d8c20 nid=0x9f18 waiting on condition  [0x00000012610ff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x000000070039b638> (a java.util.concurrent.SynchronousQueue$TransferStack)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:401)
        at java.util.concurrent.SynchronousQueue.poll(java.base@17.0.1/SynchronousQueue.java:903)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1061)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"Start Level: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #44 daemon prio=5 os_prio=0 cpu=1799109.38ms elapsed=1904.72s tid=0x000001f6bb22b8f0 nid=0x9974 runnable  [0x00000012618fe000]
   java.lang.Thread.State: RUNNABLE
        at jdk.internal.misc.Unsafe.unpark(java.base@17.0.1/Native Method)
        at java.util.concurrent.locks.LockSupport.unpark(java.base@17.0.1/LockSupport.java:177)
        at java.util.concurrent.SynchronousQueue$TransferStack$SNode.tryMatch(java.base@17.0.1/SynchronousQueue.java:263)
        at java.util.concurrent.SynchronousQueue$TransferStack.transfer(java.base@17.0.1/SynchronousQueue.java:422)
        at java.util.concurrent.SynchronousQueue.offer(java.base@17.0.1/SynchronousQueue.java:875)
        at java.util.concurrent.ThreadPoolExecutor.execute(java.base@17.0.1/ThreadPoolExecutor.java:1357)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.execute(ModuleResolver.java:1553)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor.execute(ResolverImpl.java:2502)
        at org.apache.felix.resolver.ResolverImpl.calculatePackageSpaces(ResolverImpl.java:1233)
        at org.apache.felix.resolver.ResolverImpl.checkConsistency(ResolverImpl.java:614)
        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:1038)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:992)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:909)
        at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:172)
        at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:548)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:503)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:492)
        at org.eclipse.osgi.container.Module.start(Module.java:446)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745)
        - locked <0x0000000700383580> (a java.lang.Object)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)

   Locked ownable synchronizers:
        - None

"Bundle File Closer" #45 daemon prio=5 os_prio=0 cpu=15.62ms elapsed=1904.60s tid=0x000001f6bb228da0 nid=0x62c in Object.wait()  [0x00000012619ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.Object.wait(java.base@17.0.1/Object.java:338)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:400)
        - locked <0x000000070f361950> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:341)

   Locked ownable synchronizers:
        - None

"SCR Component Actor" #46 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=1888.63s tid=0x000001f6bb22aa80 nid=0x2ec4 in Object.wait()  [0x000000125e6ff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.Object.wait(java.base@17.0.1/Object.java:338)
        at org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:83)
        - locked <0x0000000711340948> (a java.util.LinkedList)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"EMF Reference Cleaner" #49 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=1861.37s tid=0x000001f6bb229740 nid=0x8964 in Object.wait()  [0x0000001261bff000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.1/ReferenceQueue.java:155)
        - locked <0x000000071484fad0> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(java.base@17.0.1/ReferenceQueue.java:176)
        at org.eclipse.emf.common.util.CommonUtil$1ReferenceClearingQueuePollingThread.run(CommonUtil.java:70)

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-0" #51 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=456.88s tid=0x000001f6bb22af50 nid=0x9d88 runnable  [0x000000125e9fe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.accept(java.base@17.0.1/Native Method)
        at sun.nio.ch.NioSocketImpl.accept(java.base@17.0.1/NioSocketImpl.java:755)
        at java.net.ServerSocket.implAccept(java.base@17.0.1/ServerSocket.java:675)
        at java.net.ServerSocket.platformImplAccept(java.base@17.0.1/ServerSocket.java:641)
        at java.net.ServerSocket.implAccept(java.base@17.0.1/ServerSocket.java:617)
        at java.net.ServerSocket.implAccept(java.base@17.0.1/ServerSocket.java:574)
        at java.net.ServerSocket.accept(java.base@17.0.1/ServerSocket.java:532)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(jdk.management.agent@17.0.1/LocalRMIServerSocketFactory.java:52)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(java.rmi@17.0.1/TCPTransport.java:413)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(java.rmi@17.0.1/TCPTransport.java:377)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - <0x00000007223ea560> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)

"RMI Scheduler(0)" #53 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=456.85s tid=0x000001f6bb229c10 nid=0x942c waiting on condition  [0x000000125edff000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x00000007223ed220> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@17.0.1/LockSupport.java:252)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@17.0.1/AbstractQueuedSynchronizer.java:1672)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.1/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@17.0.1/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@17.0.1/ThreadPoolExecutor.java:1062)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1122)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"JMX server connection timeout 54" #54 daemon prio=5 os_prio=0 cpu=31.25ms elapsed=456.85s tid=0x000001f6bb22a0e0 nid=0x4350 in Object.wait()  [0x000000125fbff000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(java.base@17.0.1/Native Method)
        - waiting on <no object reference available>
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(java.management@17.0.1/ServerCommunicatorAdmin.java:171)
        - locked <0x00000007223eb1e0> (a [I)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - None

"RMI TCP Connection(3)-192.168.0.23" #55 daemon prio=5 os_prio=0 cpu=750.00ms elapsed=404.07s tid=0x000001f6bb22bdc0 nid=0x5c60 runnable  [0x0000001261afe000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.Net.poll(java.base@17.0.1/Native Method)
        at sun.nio.ch.NioSocketImpl.park(java.base@17.0.1/NioSocketImpl.java:181)
        at sun.nio.ch.NioSocketImpl.timedRead(java.base@17.0.1/NioSocketImpl.java:285)
        at sun.nio.ch.NioSocketImpl.implRead(java.base@17.0.1/NioSocketImpl.java:309)
        at sun.nio.ch.NioSocketImpl.read(java.base@17.0.1/NioSocketImpl.java:350)
        at sun.nio.ch.NioSocketImpl$1.read(java.base@17.0.1/NioSocketImpl.java:803)
        at java.net.Socket$SocketInputStream.read(java.base@17.0.1/Socket.java:966)
        at java.io.BufferedInputStream.fill(java.base@17.0.1/BufferedInputStream.java:244)
        at java.io.BufferedInputStream.read(java.base@17.0.1/BufferedInputStream.java:263)
        - locked <0x00000007240cb7b8> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read(java.base@17.0.1/FilterInputStream.java:82)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(java.rmi@17.0.1/TCPTransport.java:569)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(java.rmi@17.0.1/TCPTransport.java:828)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(java.rmi@17.0.1/TCPTransport.java:705)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$186/0x0000000800db41d0.run(java.rmi@17.0.1/Unknown Source)
        at java.security.AccessController.executePrivileged(java.base@17.0.1/AccessController.java:776)
        at java.security.AccessController.doPrivileged(java.base@17.0.1/AccessController.java:399)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(java.rmi@17.0.1/TCPTransport.java:704)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.1/ThreadPoolExecutor.java:1136)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.1/ThreadPoolExecutor.java:635)
        at java.lang.Thread.run(java.base@17.0.1/Thread.java:833)

   Locked ownable synchronizers:
        - <0x00000007240912c0> (a java.util.concurrent.locks.ReentrantLock$NonfairSync)
        - <0x00000007240cb978> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"VM Thread" os_prio=2 cpu=3140.62ms elapsed=1914.35s tid=0x000001f6b6de3010 nid=0x9db8 runnable  

"GC Thread#0" os_prio=2 cpu=44062.50ms elapsed=1914.35s tid=0x000001f6932ca820 nid=0x9b9c runnable  

"GC Thread#1" os_prio=2 cpu=43843.75ms elapsed=1914.12s tid=0x000001f6b885bca0 nid=0x7078 runnable  

"GC Thread#2" os_prio=2 cpu=43906.25ms elapsed=1914.12s tid=0x000001f6b7eb43c0 nid=0x2538 runnable  

"GC Thread#3" os_prio=2 cpu=43953.12ms elapsed=1914.12s tid=0x000001f6b7eb4670 nid=0x9c1c runnable  

"GC Thread#4" os_prio=2 cpu=44078.12ms elapsed=1914.12s tid=0x000001f6b7eb4920 nid=0x6f2c runnable  

"GC Thread#5" os_prio=2 cpu=43953.12ms elapsed=1914.12s tid=0x000001f6b7ea9960 nid=0x600c runnable  

"GC Thread#6" os_prio=2 cpu=43781.25ms elapsed=1914.11s tid=0x000001f6b7c77e00 nid=0x9ad8 runnable  

"GC Thread#7" os_prio=2 cpu=43859.38ms elapsed=1914.11s tid=0x000001f6b899c8b0 nid=0x81cc runnable  

"GC Thread#8" os_prio=2 cpu=43968.75ms elapsed=1914.11s tid=0x000001f6b899cb60 nid=0x31c runnable  

"GC Thread#9" os_prio=2 cpu=43937.50ms elapsed=1914.11s tid=0x000001f6b7ee3600 nid=0x7654 runnable  

"GC Thread#10" os_prio=2 cpu=43828.12ms elapsed=1914.11s tid=0x000001f6b8938440 nid=0x51c0 runnable  

"GC Thread#11" os_prio=2 cpu=43890.62ms elapsed=1914.11s tid=0x000001f6b8938b00 nid=0x9a54 runnable  

"GC Thread#12" os_prio=2 cpu=44031.25ms elapsed=1914.11s tid=0x000001f6b893b5d0 nid=0x388c runnable  

"G1 Main Marker" os_prio=2 cpu=0.00ms elapsed=1914.35s tid=0x000001f6b3d60a90 nid=0x4458 runnable  

"G1 Conc#0" os_prio=2 cpu=453.12ms elapsed=1914.35s tid=0x000001f6b3d61770 nid=0x86f8 runnable  

"G1 Conc#1" os_prio=2 cpu=453.12ms elapsed=1591.70s tid=0x000001f6b8af9b10 nid=0x75e8 runnable  

"G1 Conc#2" os_prio=2 cpu=453.12ms elapsed=1591.70s tid=0x000001f6b8af9050 nid=0x9e14 runnable  

"G1 Refine#0" os_prio=2 cpu=62.50ms elapsed=1914.35s tid=0x000001f6b3e4b4e0 nid=0x8af4 runnable  

"G1 Refine#1" os_prio=2 cpu=15.62ms elapsed=1914.11s tid=0x000001f6b8986cb0 nid=0x9134 runnable  

"G1 Refine#2" os_prio=2 cpu=15.62ms elapsed=1913.69s tid=0x000001f6bad8f3f0 nid=0x92e4 runnable  

"G1 Refine#3" os_prio=2 cpu=15.62ms elapsed=1913.69s tid=0x000001f6ba535440 nid=0x841c runnable  

"G1 Refine#4" os_prio=2 cpu=0.00ms elapsed=1913.69s tid=0x000001f6b89e5ae0 nid=0x8bc runnable  

"G1 Refine#5" os_prio=2 cpu=0.00ms elapsed=1913.69s tid=0x000001f6b988b110 nid=0x7278 runnable  

"G1 Refine#6" os_prio=2 cpu=0.00ms elapsed=1913.69s tid=0x000001f6ba673ed0 nid=0x8328 runnable  

"G1 Refine#7" os_prio=2 cpu=0.00ms elapsed=1913.69s tid=0x000001f6b9032390 nid=0x204c runnable  

"G1 Service" os_prio=2 cpu=125.00ms elapsed=1914.35s tid=0x000001f6b3e4b8b0 nid=0x4a6c runnable  

"StringDedupProcessor" os_prio=2 cpu=109.38ms elapsed=1914.35s tid=0x000001f6b3f106d0 nid=0x3844 runnable  

"VM Periodic Task Thread" os_prio=2 cpu=296.88ms elapsed=1914.32s tid=0x000001f6b706e630 nid=0x7cec waiting on condition  

JNI global refs: 27, weak refs: 0

Any update to that installation takes forever or restart; we're talking more than 1/2 hour where you get the impression it's hung or deadlocked.

Did something change in the resolver implementation? Are we using so many more detailed OSGi dependencies (package imports with uses) that causes this to becomes super expensive?

laeubi commented 2 years ago

Duplicate of #84

laeubi commented 2 years ago

You can find some insights here:

merks commented 2 years ago

Yes, look similar but there are lots of mergeUses that don't appear blocked. Maybe the additional details here are helpful for the other issue...

laeubi commented 2 years ago

Actually this is not blocking at all, its just a lots of heavy computation going on, so the actual outcome of the dump depends on when it was taken.

merks commented 2 years ago

Yes, sometimes its doing this:

"Start Level: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #44 daemon prio=5 os_prio=0 cpu=2597312.50ms elapsed=2751.45s tid=0x000001f6bb22b8f0 nid=0x9974 runnable  [0x00000012618fd000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.util.OpenHashMapList.deepClone(OpenHashMapList.java:37)
        at org.apache.felix.resolver.Candidates.copy(Candidates.java:1143)
        at org.apache.felix.resolver.ResolverImpl.permuteUsedBlames(ResolverImpl.java:1598)
        at org.apache.felix.resolver.ResolverImpl.checkPackageSpaceConsistency(ResolverImpl.java:1464)
        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:1038)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:992)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:909)
        at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:172)
        at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:548)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:503)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:492)
        at org.eclipse.osgi.container.Module.start(Module.java:446)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745)
        - locked <0x0000000700383580> (a java.lang.Object)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)

But after waiting 45 minutes so far, it feels like a non-terminating NP-complete process.

merks commented 2 years ago

I guess only that one thread is doing something

"Start Level: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #44 daemon prio=5 os_prio=0 cpu=2798765.62ms elapsed=2961.00s tid=0x000001f6bb22b8f0 nid=0x9974 runnable  [0x00000012618fd000]
   java.lang.Thread.State: RUNNABLE
        at java.util.HashMap$HashIterator.nextNode(java.base@17.0.1/HashMap.java:1601)
        at java.util.HashMap$KeyIterator.next(java.base@17.0.1/HashMap.java:1620)
        at org.apache.felix.resolver.ResolverImpl.mergeUses(ResolverImpl.java:1040)
        at org.apache.felix.resolver.ResolverImpl.computeUses(ResolverImpl.java:887)
        at org.apache.felix.resolver.ResolverImpl.access$6(ResolverImpl.java:810)
        at org.apache.felix.resolver.ResolverImpl$6.run(ResolverImpl.java:1237)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor$1.run(ResolverImpl.java:2490)
        at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.1/Executors.java:539)
        at java.util.concurrent.FutureTask.run(java.base@17.0.1/FutureTask.java:264)
        at java.util.concurrent.ThreadPoolExecutor$CallerRunsPolicy.rejectedExecution(java.base@17.0.1/ThreadPoolExecutor.java:2037)
        at java.util.concurrent.ThreadPoolExecutor.reject(java.base@17.0.1/ThreadPoolExecutor.java:833)
        at java.util.concurrent.ThreadPoolExecutor.execute(java.base@17.0.1/ThreadPoolExecutor.java:1365)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.execute(ModuleResolver.java:1553)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor.execute(ResolverImpl.java:2502)
        at org.apache.felix.resolver.ResolverImpl.calculatePackageSpaces(ResolverImpl.java:1233)
        at org.apache.felix.resolver.ResolverImpl.checkConsistency(ResolverImpl.java:614)
        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:1038)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:992)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:909)
        at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:172)
        at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:548)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:503)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:492)
        at org.eclipse.osgi.container.Module.start(Module.java:446)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745)
        - locked <0x0000000700383580> (a java.lang.Object)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)
laeubi commented 2 years ago

But after waiting 45 minutes so far, it feels like a non-terminating NP-complete process.

NP problems are still terminating but might take very long, and what OSGi needs to compute here is the Boolean satisfiability problem what is NP-hard as per todays knowledge.

vogella commented 2 years ago

cc @jukzi

merks commented 2 years ago

After 1 hour of thread dumps, it's still here:

"Start Level: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #44 daemon prio=5 os_prio=0 cpu=5011156.25ms elapsed=5276.92s tid=0x000001f6bb22b8f0 nid=0x9974 waiting on condition  [0x00000012618fe000]
   java.lang.Thread.State: WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@17.0.1/Native Method)
        - parking to wait for  <0x00000007b4af1830> (a java.util.concurrent.FutureTask)
        at java.util.concurrent.locks.LockSupport.park(java.base@17.0.1/LockSupport.java:211)
        at java.util.concurrent.FutureTask.awaitDone(java.base@17.0.1/FutureTask.java:447)
        at java.util.concurrent.FutureTask.get(java.base@17.0.1/FutureTask.java:190)
        at org.apache.felix.resolver.ResolverImpl$EnhancedExecutor.await(ResolverImpl.java:2522)
        at org.apache.felix.resolver.ResolverImpl.calculatePackageSpaces(ResolverImpl.java:1196)
        at org.apache.felix.resolver.ResolverImpl.checkConsistency(ResolverImpl.java:614)
        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:1038)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:992)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:909)
        at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:172)
        at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:548)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:503)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:492)
        at org.eclipse.osgi.container.Module.start(Module.java:446)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745)
        - locked <0x0000000700383580> (a java.lang.Object)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)
jukzi commented 2 years ago

I have seen similar stacktraces whenever i update my eclipse IDE too (but never longer then 10min), but do not know how to reproduce it in the IDE. If someone provides a reproducer that i can debug then i could try to make it faster.

HannesWell commented 2 years ago

But after waiting 45 minutes so far, it feels like a non-terminating NP-complete process.

NP problems are still terminating but might take very long, and what OSGi needs to compute here is the Boolean satisfiability problem what is NP-hard as per todays knowledge.

I wonder if it could be useful to use some simpler heuristic to compute an approcimative solution first and check if it is worth to compute an exact solution using an exact algorithm, for cases that are expected to run long.

Depending in the problem one can be lucky and have good-natured problem-instances that can be solved (almost) optimal with heuristic algorithms that terminatr in polynomial time.

But all that has to be done in the Felix resolver. For now In think the quickest fix ist what Christoph suggested in https://github.com/eclipse-equinox/equinox/issues/84#issuecomment-1191254395.

laeubi commented 2 years ago

Just in case someone is interested in the details some can be found here: https://github.com/eclipse/tycho/issues/213#issuecomment-920008047

laeubi commented 2 years ago

I wonder if it could be useful to use some simpler heuristic to compute an approcimative solution first and check if it is worth to compute an exact solution using an exact algorithm, for cases that are expected to run long.

Solving the NP problem is considered a millennium problem rewarded by 1 million US $ so please let us know when you find a solution this might solve the "e have not enough developer resources" problem as well :-)

But all that has to be done in the Felix resolver.

Exactly, or Equinox needs to implement an own resolver, I have recommended a while back already to think about merging P2+Equinox resolver but that's nothing to solve in a few hours.

At least both (P2 and Felix) can compute a solution fast when you disable use-clauses, so it might we worth to first compute a solution that is not unique and then start with the non-unique solution.

The problem in general is, that for all "simple" problems this already terminates fast, and the "problematic ones" run slow, so one might end with a similar long runtime anyways. I already noted that LSP4J/LSP4E are giving a hard time to the resolver so it heavily depends on what you are using, there was one example with birt a while back, but I can't reproduce it with the current master (e.g. with -Dtycho.version=2.7.4 -Dtycho.equinox.resolver.uses=true -Dtycho.equinox.resolver.batch.size=10000)

merks commented 2 years ago

Four hours later, and still running:

"Start Level: Equinox Container: b75ed7a6-8ac6-4973-b0db-b15f20689f61" #44 daemon prio=5 os_prio=0 cpu=21477562.50ms elapsed=22382.75s tid=0x000001f6bb22b8f0 nid=0x9974 runnable  [0x00000012618fd000]
   java.lang.Thread.State: RUNNABLE
        at org.apache.felix.resolver.util.OpenHashMapList.deepClone(OpenHashMapList.java:35)
        at org.apache.felix.resolver.Candidates.copy(Candidates.java:1143)
        at org.apache.felix.resolver.ResolverImpl.permuteUsedBlames(ResolverImpl.java:1598)
        at org.apache.felix.resolver.ResolverImpl.checkPackageSpaceConsistency(ResolverImpl.java:1464)
        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:1038)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolveRevisionsInBatch(ModuleResolver.java:992)
        at org.eclipse.osgi.container.ModuleResolver$ResolveProcess.resolve(ModuleResolver.java:909)
        at org.eclipse.osgi.container.ModuleResolver.resolveDelta(ModuleResolver.java:172)
        at org.eclipse.osgi.container.ModuleContainer.resolveAndApply(ModuleContainer.java:548)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:503)
        at org.eclipse.osgi.container.ModuleContainer.resolve(ModuleContainer.java:492)
        at org.eclipse.osgi.container.Module.start(Module.java:446)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel$2.run(ModuleContainer.java:1847)
        at org.eclipse.osgi.internal.framework.EquinoxContainerAdaptor$1$1.execute(EquinoxContainerAdaptor.java:136)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1840)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.incStartLevel(ModuleContainer.java:1781)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.doContainerStartLevel(ModuleContainer.java:1745)
        - locked <0x0000000700383580> (a java.lang.Object)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1667)
        at org.eclipse.osgi.container.ModuleContainer$ContainerStartLevel.dispatchEvent(ModuleContainer.java:1)
        at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:234)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:345)

Here's what I did...

Use the installer's advanced mode to install Committer 2022-06 and on the second/Project page, include CDO's setup:

image

Let the whole thing finish creating and provisioning the IDE.

Use Navigate -> Open Setup -> Installation to open the Installation.setup. Double click the root object and change the product version to the 2022-09 committer version:

image'

Be sure to save the file:

image

Use Help -> Perform Setup Tasks. You only need to run the p2 task:

image

This is the equivalent of updating 2022-06 to 2022-09 (M1 at the moment).

When it's done, the status area will flash a warning icon. Then you can click that icon and click finish to restart:

image

I'm not sure if such an IDE ever finishes starting, I'm letting it run further.

In other similar scenarios it "only" took 10-20 minutes to restart, but this one seems especially complicated/slow...

laeubi commented 2 years ago

@merks I think @tjwatson maybe could tell while the timeout of two minutes do not apply here, but have you tried e.g.

-Dequinox.resolver.revision.batch.size=1 or -Dequinox.resolver.batch.timeout=5000

merks commented 2 years ago

Of course I never tried those and never would have thought to try such things. 😢

I tried this just now, and it starts immediately:

./eclipse.exe  -clean -vmargs -Dequinox.resolver.revision.batch.size=1

I added the -clean to force it to do a lot of work. So goodness only knows what the one process has been doing for the past 5 hours that apparently can be done in a few seconds depending on the "batch size"...

laeubi commented 2 years ago

Of course I never tried those and never would have thought to try such things. cry

They are mentioned in the link I mentioned jut right after your report :-)

So goodness only knows what the one process has been doing for the past 5 hours that apparently can be done in a few seconds depending on the "batch size"...

@tjwatson can better explain the details (see https://github.com/eclipse/tycho/issues/213#issuecomment-920008047 for some explanation), but strictly speaking it is about resolving "all at once" versus "resolve one after the other", sadly it seems there is no isolated test-case for this so investigate what exactly going on (maybe one can zip such a "wait for ever install" but it would still be huge), so maybe:

  1. The problem is simply hard to solve
  2. There is a bug in the Felix resolver that leads to some non-deterministic behavior e.g. it uses some weak or soft references that get cleared out and thus can running into circles, or some kind of bad handling of already invalid solutions (I don't know if Felix uses as SAT-Solver or some kind of Backtracking?)
  3. ... something other is going wrong .... e.g exhaustive copy of objects that makes the GC going mad ...
merks commented 2 years ago

@laeubi In my defense I was in a hurry to get to the lake. It's 33C here today! 😱

I can empathize that it's annoying when the problem is complex and hard to reproduce. I have had a similar issue now in a number of installations already, so it seems not an isolated problem. One can imaging that if this happens to a naive user, they will be very unimpressed. If it happens to lots of users (after the 2022-09 release) that is just very bad for Eclipse as a whole. I've never seen this problem before so it seems that something has changed to make it happen at all or to make it much worse than ever was before. Any theories about what's different now?

laeubi commented 2 years ago

Any theories about what's different now?

Something has changed :-)

But it is not "new" in that i is only happen now see for example mentioned here back in 2017 and here at 2015, the only thing I found out until now is that it seem to happen when there are some very narrow version requirements and many choices, maybe rexport and split packages makes it even worse then ...

Beside that I think @tjwatson might be able to give better guidance, according to him there should be a timeout of 2 minutes (!) before Equinox automatically switch to the batchsize=1 so even if thats a long time for a human being and decades for your computer, there is obviously something here that prevents this emergency stop switch to kick in ...

tjwatson commented 2 years ago

Do you happen to have a log where logs of resolution issues were logged during this process? The fact that you are seeing this happen during org.eclipse.osgi.container.Module.start(Module.java:446) indicates to me that we got past the "big" resolves that either the EclipseStarter did against the initial bundle set (typically only includes org.eclipse.equinox.simpleconfigurator). But we do not see org.eclipse.core.runtime.adaptor.EclipseStarter.refreshPackages(Bundle[]) on the call stack so it seems we got past trying to resolve the newly installed simpleconfigurator.

What should happen next is the start of simpleconfigurator. It should uninstall/install all the necessary bundles for the update and then eventually call org.eclipse.equinox.internal.simpleconfigurator.ConfigApplier.refreshAllBundles() to force all the bundles to be refreshed and resolved "at once". This approach was added some time ago to mimic what resolution would happen if you did a -clean. But we get passed this resolution. But now we must be left with some bundles that could not resolve with that process because now when we try to increment the start-level to the final active start-level it will try to start all the bundle (most lazily). But even for lazy activated bundles the framework first checks if the bundle is resolved, if not it tries to resolve it (again!). It is here that we appear to be "taking forever".

If you have a state you can connect with a debugger it would be helpful to know if you did enter/exit org.eclipse.equinox.internal.simpleconfigurator.ConfigApplier.refreshAllBundles() and are now continuing on to starting up to the final start-level.

rotty3000 commented 2 years ago

I'm not sure if this is the case here, but the Felix resolver seems to have an issue with deciding which is the correct Provider to select among a list of candidates whose only differentiating attribute is version and in the micro range. Further, I believe that as the number of potential candidates grows the complexity becomes exponentially more difficult for the resolver to eliminate them because particularly for packages, the micro version range is essentially not a differentiation which means there's no criteria for eliminating those chains...

tjwatson commented 2 years ago

I'm not sure if this is the case here, but the Felix resolver seems to have an issue with deciding which is the correct Provider to select among a list of candidates whose only differentiating attribute is version and in the micro range. Further, I believe that as the number of potential candidates grows the complexity becomes exponentially more difficult for the resolver to eliminate them because particularly for packages, the micro version range is essentially not a differentiation which means there's no criteria for eliminating those chains...

It is true that if we have many requirements that can match many of the same candidate suppliers then the combinations that can be tried grows exponentially. If there is no solution then the algorithm will explode. I thought we had safe guards that would reduce this with a timeout. But here I fear we are in a situation where 100s of bundles are not resolvable and the framework keeps trying to re-resolve them each time we move on to try and start the next bundle in the list of bundles to start during initial start.

This reminds me of an idea I had implemented in the old Equinox resolver for reducing combinations by merging candidate lists when they had identical lists of candidates (https://bugs.eclipse.org/bugs/show_bug.cgi?id=181327)

Today if 100 bundles Import-Package: foo and there are 3 different foo candidates that can match the requirement from each 100 bundles, but all 3 candidates always result in a conflict that is not solvable the resolver has 100^3 combinations to try before giving up. My idea in https://bugs.eclipse.org/bugs/show_bug.cgi?id=181327 was to instead treat the 100 requirements that all have the same candidates list as one list of 3 to permute over instead of 100 lists of 3 to permute over.

It has been a long time, but if I recall correctly this approach does throw out some valid combinations that could hold the secret solution that is consistent. But I also don't recall a single real situation where that caused an actual problem that did not resolve.

One reason I have not looked into this approach is because I thought we had a timeout "solution" that would back off after some timeout and try resolving a much smaller group of bundles such that the number of permutations to try was manageable. I suspect this is not getting exercised properly because we keep trying to resolve over and over as we try to start each unresolveable bundle.

merks commented 2 years ago

I'll try to find time to remote debug tomorrow. I just killed the process now after one of the nearby nuclear power plants got overloaded...

merks commented 2 years ago

@tjwatson

Yes we got past org.eclipse.equinox.internal.simpleconfigurator.ConfigApplier.refreshAllBundles() and then called org.eclipse.equinox.internal.simpleconfigurator.ConfigApplier.startBundles(Bundle[]).

It looks like this after a few minutes, so quite large maps involved.

image

I'm just not sure what useful information I should try to collect via the debug session.

tjwatson commented 2 years ago

Are there any logs in configuration/ folder with resolution errors? The log will be in configuration/ with some timestamp.log name because we don't have a workspace yet.

tjwatson commented 2 years ago

One possible improvement could be to stash away a ResolutionReport in the framework and keep track of the ModuleDatabase stamp. If resolution failed in one pass (I think from when ConfigApplier.refreshAllBundles() got called) we just keep trying again and again each time an unresolved bundle is started later. If you have a large number of bundles that failed resolution then this will just happen over and over, likely with the exact same outcome from a ResolutionReport. We could check the ModuleDatabase timestamp and avoid another resolution if nothing has changed to add new capabilities for resolution.

One reason we cannot do this though is I think that it would violate the contract with ResolverHook services. The specification for starting a bundle indicates that an attempt to resolve must be made if you try to start a bundle that is not resolved. This is observable from a ResolverHook. So it is unclear we can just ignore that for each unresolved bundle that gets started.

merks commented 2 years ago

No, there is no log:

image

After 1 hour, there is only one thread doing useful/interesting work:

image

Maybe there is useful detail in the variables the ResolverImpl.checkPackageSpaceConsistency(ResolveSession, Resource, Candidates, boolean, Map<Resource, Packages>, Map<Resource, Object>) method?

image

Maybe this is useful:

image

merks commented 2 years ago

I'm not sure it ever leaves this method but rather stays in the loop "forever":

image

laeubi commented 2 years ago

@merks it will breaks if allCandidates = null, but this might never be reached?

merks commented 2 years ago

There is also the while condition. In any case, the point it seemly never gets the breakpoint on the return statement...

vogella commented 2 years ago

We see a similar delay in a client RCP application in the same code path. @merks did you solve this issue for you?

merks commented 2 years ago

I've seen the same issue again yesterday creating a brand new 2022-09-base installation. The only workaround is using this option:

-Dequinox.resolver.revision.batch.size=1

But I really don't know the implication of that and it seems to me this problem is new to 2022-09. Hence I've already asked Any theories about what's different now? New resolver implementation? More use of package imports? Changes to the TP that result in more different bundles but with the same exported packages leading to more complicated wiring problems to resolve? I don't know but no one seems to have a theory of what's new and different now. I'm happy to help debug things but I have no good knowledge of what's going on here...

vogella commented 2 years ago

I've seen the same issue again yesterday creating a brand new 2022-09-base installation. The only workaround is using this option:

-Dequinox.resolver.revision.batch.size=1

But I really don't know the implication of that and it seems to me this problem is new to 2022-09. Hence I've already asked Any theories about what's different now? New resolver implementation? More use of package imports? Changes to the TP that result in more different bundles but with the same exported packages leading to more complicated wiring problems to resolve? I don't know but no one seems to have a theory of what's new and different now. I'm happy to help debug things but I have no good knowledge of what's going on here...

I have seem multiple commits moving require-bundle to import packages (which is the recommended way according to the OSGi spec), so I would say, yes we have more import package statements.

merks commented 2 years ago

@vogella Yes, I expect we do have more package imports. We've removed bundle includes from features which allows more flexibility of bundle versions. But whether that's a cause or not is just a theory backed up by zero facts.

I have a self-contained installation (using the steps above, but without a bundle pool) that reproduces the problem. Someone more knowledgeable could remote debug the problem. Unfortunately that zip is 783MB. I wonder how best to share such a very large zip?

laeubi commented 2 years ago

@merks if you have a comparable installation, it might be good to simply diff the plugins folder to see whats new.

You also might reduce the size by strip of JustJ (if its included), and it might be possible to get a (temporary) FTP account on download.eclipse.org to updload the file? At least if such an install could be created in some automated/scripted way you can upload is using a custom build job on the jenkins CI ....

merks commented 2 years ago

@tjwatson

I've temporarily put this eclipse.zip with the installation on a Google drive:

https://drive.google.com/file/d/1uwD9v71k0ygfiLj5MDXLrESIynT1LwpN/view?usp=sharing

Anyone who wants to try to help debug this problem, please download the zip sooner rather than later.

tjwatson commented 2 years ago

I cannot promise I will have the necessary time to debug this issue. If this is determined to be a blocking issue for release I would consider temporarily changing the default of the equinox.resolver.revision.batch.size. When you set that to 1 does it result in no unresolved bundles?

merks commented 2 years ago

@tjwatson I fully understand. I'm really not sure how prevalent this problem is nor how likely users are to encounter this updating from 2022-06 to 2022-09. I think @jonahgraham quite often tests that for EPP packages...

Good question about unresolved bundles because when I run like this:

$eclipse/eclipse.exe -debug -consolelog -data ws -vmargs -Dequinox.resolver.revision.batch.size=1 2>&1 | tee log

A whole whack of things appear to be failing!

log.txt

jonahgraham commented 2 years ago

I think @jonahgraham quite often tests that for EPP packages...

I do a test update of (typically) one EPP package from the last R release to the current build to make sure it upgrades cleanly. I haven't seen such startup issues.

laeubi commented 2 years ago

By the way might be related Felix issue: https://issues.apache.org/jira/browse/FELIX-5648

tjwatson commented 2 years ago

@tjwatson

I've temporarily put this eclipse.zip with the installation on a Google drive:

https://drive.google.com/file/d/1uwD9v71k0ygfiLj5MDXLrESIynT1LwpN/view?usp=sharing

Anyone who wants to try to help debug this problem, please download the zip sooner rather than later.

I don't have windows available to try that out on, but I followed the steps you provided to reproduce and I think I have it in an endless resolve now.

tjwatson commented 2 years ago

I found one issue with the way Equinox uses the Felix Resolver implementation. We always try to resolve all the bundles (optionally) when calling something like Bundle.start on an unresolved bundle. I don't think this is necessary and there is a bug in the way we do this because we don't let the second call to the resolver for the optional unresolved bundles (the ones not having Bundle.start called on them) to timeout. This is why we see cases where the algorithm explodes and never times-out.

I have a draft PR #95 but I didn't have time to test it out in the "Ed" scenario. @merks if you manage to have time to build this and try it out in your scenario that would be good. I don't think you will be altogether happy with the results though because I think you likely are in an unresolvable state here.

laeubi commented 2 years ago

@tjwatson (or anyone else interested in this problem) if you like to easier debug this (no p2, no simpleconfigurator, no restarts...), I created a test-runner for this using the great connect framework facility:

  1. download the example project from @merks
  2. download equinox-test.zip extract it and import it into a workspace with equinox
  3. Start test.ProductToTestCaseTransformer and pass it the folder (e.g. /tmp/resolver-bug/eclipse)

This blocks "forever" at the start (!) of the framework that is no user bundle is marked for start nor is it started at all (I removed all bundle activators and all DS components from the manifest declaration), all my 16 CPUs are getting nearly 100% CPU load and I killed it after a few minute to not overheat them ;-)

I did not set any special properties, just the framework location is set to the users tmp folder + "resolver-test"

merks commented 2 years ago

@tjwatson I think you hit the nail on the head! Even with remote debug one can often use hot replace to make changes so I tried your change in my SDK IDE and then the remote debugged IDE started in just seconds (after the hot replace) with this in the log:

log.txt

laeubi commented 2 years ago

As I have seen this a lot in the logs:

because it is exposed to package 'org.w3c.dom.events' from resources org.eclipse.osgi [osgi.identity; osgi.identity="org.eclipse.osgi"; type="osgi.bundle"; version:Version="3.18.100.v20220726-1348"; singleton:="true"] and org.w3c.dom.events [osgi.identity; osgi.identity="org.w3c.dom.events"; type="osgi.bundle"; version:Version="3.0.0.draft20060413_v201105210656"] via two dependency chains

I also has noticed this in the past with Tycho and one can "fix" the problem by also importing org.w3c.dom