Is a 14-Minute Startup Time Normal for OpenHAB?

milo · January 15, 2025, 5:04am

I’ve noticed that my OpenHAB instance takes around 14 minutes to fully start, as seen in my logs. I’m wondering if this is normal for my setup or if there’s a way to optimize the startup process. Here are the details:

Log Snippets:

2025-01-13 21:25:17.810 [INFO ] [org.openhab.core.Activator          ] - Starting openHAB 4.3.2 (Release Build)
2025-01-13 21:36:37.708 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2025-01-13 21:39:10.897 [INFO ] [nal.WeatherCalculatorEventSubscriber] - Receive Update: Item 'Speed_Outdoor_WeatherFlowTempestWindAvgSpeed' changed from 0.93 m/s to 0.86 m/s

Here is detailed log with trace logging

System Details:

OpenHAB Version: 4.3.2
Operating System: openhabian on a Raspberry Pi 4B with 8GB RAM
Add-ons Installed: sensorcommunity,ntp,dwdpollenflug,openweathermap,network,astro,exec,systeminfo,mqtt,lgwebos,yamahareceiver,hue,mail,openuv,icalendar,tr064,http,yioremote,logreader,volumio,deconz,shelly,kodi,pihole
Persistence: mysql
Number of Things: 100
Number of Items: 734

Observations:

The initial log entry at 21:25:17 indicates openhab starts.
It takes ~11 minutes before my sitemap begins loading.
Updates start coming through after ~14 minutes.

Is this normal for OpenHAB on my hardware/setup? Are there specific logs or diagnostics I can check to identify bottlenecks?

During startup, top shows OpenHAB as the primary process with some disk I/O.

All other processes remain idle

Thanks for your help!

jimtng · January 15, 2025, 5:34am

Uninstall all bundles, and install them back one at a time.
The easiest way to do this is adding them into addons.cfg.
But beware that usually the first run when installing a binding will take longer

milo · January 15, 2025, 10:04am

Hello I see these issue

ThreadId: 32 ThreadName: CM Configuration Updater ThreadState: WAITING
Jan 15 10:04:03 smarthome karaf[11272]:   Blocked On: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@4867893d LockOwnerId: -1 LockOwnerName: null
Jan 15 10:04:03 smarthome karaf[11272]:   Synchronizers Locked: none
Jan 15 10:04:03 smarthome karaf[11272]:   Monitors Locked: none
Jan 15 10:04:03 smarthome karaf[11272]:   Stack Trace:
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/jdk.internal.misc.Unsafe.park(Native Method)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3465)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3436)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1630)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:485)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:673)
Jan 15 10:04:03 smarthome karaf[11272]:     org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:73)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.lang.Thread.run(Thread.java:840)
Jan 15 10:04:03 smarthome karaf[11272]: ThreadId: 33 ThreadName: CM Event Dispatcher ThreadState: WAITING
Jan 15 10:04:03 smarthome karaf[11272]:   Blocked On: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@6bd78a79 LockOwnerId: -1 LockOwnerName: null
Jan 15 10:04:03 smarthome karaf[11272]:   Synchronizers Locked: none
Jan 15 10:04:03 smarthome karaf[11272]:   Monitors Locked: none
Jan 15 10:04:03 smarthome karaf[11272]:   Stack Trace:
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/jdk.internal.misc.Unsafe.park(Native Method)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.LockSupport.park(LockSupport.java:341)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:506)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3465)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3436)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1630)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.LinkedBlockingDeque.takeFirst(LinkedBlockingDeque.java:485)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.util.concurrent.LinkedBlockingDeque.take(LinkedBlockingDeque.java:673)
Jan 15 10:04:03 smarthome karaf[11272]:     org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:73)
Jan 15 10:04:03 smarthome karaf[11272]:     java.base@17.0.13/java.lang.Thread.run(Thread.java:840)

rlkoshak · January 15, 2025, 3:07pm

There seems to be a full minute between these steps:

2025-01-14 22:22:27.213 [DEBUG] [irmwareUpdateConsoleCommandExtension] - bundle org.openhab.core.thing:4.3.2 (221)[org.openhab.core.thing.internal.console.FirmwareUpdateConsoleCommandExtension(285)] : Querying state unsatisfiedReference
2025-01-14 22:23:20.582 [TRACE] [re.storage.json.internal.JsonStorage] - deserialized value 'DiscoveryResult [thingUID=weatherflowsmartweather:hub:HB-00026268, properties={serial_number=HB-00026268}, representationProperty=null, flag=NEW, label=SmartWeather Hub, bridgeUID=null, ttl=-1, timestamp=2025-01-14T21:23:10.625889864Z]' from Json
2025-01-14 22:23:20.583 [TRACE] [re.storage.json.internal.JsonStorage] - deserialized value 'DiscoveryResult [thingUID=weatherflowsmartweather:hub:HB-00026268, properties={serial_number=HB-00026268}, representationProperty=null, flag=NEW, label=SmartWeather Hub, bridgeUID=null, ttl=-1, timestamp=2025-01-14T21:23:20.580603421Z]' from Json
2025-01-14 22:23:20.584 [DEBUG] [g.discovery.internal.PersistentInbox] - Updated discovery result for 'weatherflowsmartweather:hub:HB-00026268'.
2025-01-14 22:23:20.585 [TRACE] [internal.events.ThreadedEventHandler] - inspect event: org.osgi.service.event.Event [topic=openhab] {topic=openhab/inbox/weatherflowsmartweather:hub:HB-00026268/updated, type=InboxUpdatedEvent, payload={"flag":"NEW","label":"SmartWeather Hub","properties":{"serial_number":"HB-00026268"},"thingUID":"weatherflowsmartweather:hub:HB-00026268","thingTypeUID":"weatherflowsmartweather:hub"}, timestamp=1736889800584}
2025-01-14 22:23:20.586 [TRACE] [ab.core.internal.events.EventHandler] - Skip event subscriber (class org.openhab.binding.weatherflowsmartweather.event.WeatherFlowEventSubscriberImpl) because of its filter.
2025-01-14 22:23:20.587 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.websocket.event.EventWebSocketAdapter).
2025-01-14 22:23:20.587 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.rest.sse.internal.listeners.SseEventSubscriber).
2025-01-14 22:23:20.588 [TRACE] [ab.core.internal.events.EventHandler] - Delegate event to subscriber (class org.openhab.core.io.monitor.internal.EventLogger).
2025-01-14 22:23:20.588 [TRACE] [.openhab.core.io.rest.SseBroadcaster] - broadcast to potential 0 sinks

I don’t see any other large gaps in the logs. It just seems to take a long time to do what it’s doing.

milo · January 16, 2025, 11:12am

I updated or I moved to dietpi and now startup time is 1minutes

rlkoshak · January 16, 2025, 2:33pm

That’s a very interesting and unusual result. You were on openHABian before or just Raspberry Pi OS with OH installed through apt?

milo · January 16, 2025, 3:05pm

Yes, I was on latest openhabian…

I thought about simply reinstalling openhabian but than had several issues with the image including no hotspot etc…So decided to move over completely on all devices to dietpi…moved the complete configuration over via openhab-cli backup and feeling happy with startup Time about 1min. and 30s.

Regards

mstormi · January 17, 2025, 9:32pm

That now should be fixed with 1.9.5 (although you could have used Ethernet).

Did you use the 64 bit image? If so, try again with the 32bit one.
Watch SD activity on startup (iostat -x 1). If I was to guess, there’s a lot of paging activity.
Let me know the output of ‘java -version’ on your dietPi box and how large the java process is (and how much resident).

milo · January 17, 2025, 9:56pm

I was on 64bit version…

How do I check

how large the java process is (and how much resident).

# ps -o pid,vsz,rss,comm -p 773
    PID    VSZ   RSS COMMAND
    773 6583488 1641520 java

 java -version
openjdk version "17.0.13" 2024-10-15
OpenJDK Runtime Environment (build 17.0.13+11-Debian-2deb12u1)
OpenJDK 64-Bit Server VM (build 17.0.13+11-Debian-2deb12u1, mixed mode, sharing)

I am happy now with my dietpi installation I will not change over again…

mstormi · January 17, 2025, 10:55pm

thanks for the data.

Your choice. But you will have to do all maintenance and 3rd party stuff manually then.
And with any issues, you’re on your own from now on, no other dietpi users I know of so good luck.