Hi, I keep noticing that my system starts to generate timeout messages after a short time when testing JRuby scripts. (system: current Openhabian (4.1.1) on as Raspberry 4B/4GB)
The messages are of the type:
2024-03-22 20:42:45.222 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@92ed64' takes more than 5000ms.
The more often I save a script, the more messages appear.
Then it doesn’t help to wait, I have to restart Openhab.
The problem does not occur when I test DSL rules - only when I test JRuby scripts.
Not much is included there. I tried out a few variations because I didn’t know the exact structure.
You can still see a few previous attempts commented out.
(The large commented-out block below comes from another script that I used as a reference. However, the block was commented out from the beginning.)
java_import java.time.format.DateTimeFormatter
rule 'glob_zwave_checker_warn' do
cron '0 0 12 * * Sun'
run{
logger.info("glob_zwave_checker_warn start")
#things.select { |thing| thing.uid.binding_id == "zwave" && thing.properties.key?("lastwakeup") }
things.select { |thing| thing.uid.binding_id == "zwave" && thing.properties.key?("zwave_lastwakeup") }
.each do |thing|
#logger.info("node: '#{thing.name}' - last wakup: '#{thing.zwave_lastwakeup}'")
#logger.info("node: #{thing.properties.zwave_lastwakeup}")
logger.info("node: #{thing} - #{thing.properties["zwave_lastwakeup"]}")
end
logger.info("glob_zwave_checker_warn end")
}
end
# # alle Batterien nach Ladezustand sortieren
# sorted_items_by_battery_level = IH_BatteryLevels.members
# .select(&:state) # only include non NULL / UNDEF members
# .sort_by(&:state)
#
# # Batterien mit zu geringem Ladezustand zu Meldung zusammenfassen
# sorted_items_by_battery_level.each { | item |
# if item.state < minLevel
#
# itemvalue = "#{item.state}\n"
# message = message << "\t#{item.label} - " << itemvalue
#
# positions[posIndex] = message.length - itemvalue.length - 1
# positions[posIndex+1] = (message.length - 1) - positions[posIndex]
#
# logger.info("1 #{positions[posIndex]}")
# logger.info("2 #{positions[posIndex+1]}")
# posIndex = posIndex + 2
# end
# }
#
# if message.length > 0
# message_head = "Achtung, folgende Batterien sollten bald ausgetauscht werden:\n\n"
# format_strings = ""
#
# for a in 0..((positions.size() / 2) - 1) do
# positions[a] = positions[a] + message_head.length
# format_strings = format_strings << %(#{positions[a]}:#{positions[a+1]}:BOLD)
# end
#
# logger.info(format_strings)
#
# result = Exec.execute_command_line(3.minutes, "signal-cli", "--config", "/var/lib/signal-cli", "-a", "+xxxxxxxxxxxx", "send", "-m", message_head<<message, "+xxxxxxxxxxxx", "--text-style", format_strings)
# logger.info(result)
# end
After I have saved a few times (max. 5-10 times) to try out changed source code, I usually start to get timeouts (every 5 to 10 minutes). If I then save a few more times, I have heaps of timeouts.
Yesterday evening I got the first timeouts after testing and then stopped programming. The timeouts continue to occur sporadically until this morning:
....
....
2024-03-23 01:32:20.985 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@92ed64' takes more than 5000ms.
2024-03-23 01:45:00.782 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@92ed64' takes more than 5000ms.
....
....
....
2024-03-23 07:05:43.413 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@92ed64' takes more than 5000ms.
....
....
It’s not just this JRuby script either. I’ve noticed this problem several times with other JRuby scripts, but I can’t say for sure whether it’s always the case.
I can’t see anything there that would cause it. Have you tried modifying and saving a rulesdsl file in the same manner (5+ modify e.g. add a character in a comment and save)?
Twenty times I saved a changed a rules-dsl file and run the rule every time manually. After that I waited 30 minutes - nothing happens:
2024-03-23 14:46:28.566 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:46:49.373 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:47:02.759 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:47:43.145 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:48:37.033 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:48:37.509 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:49:24.120 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:49:24.646 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:49:40.729 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:49:41.187 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:50:09.386 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:50:09.932 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:50:29.839 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:50:30.322 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:50:50.295 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:50:50.853 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:51:08.304 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:51:08.798 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:51:29.629 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:51:30.163 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:51:46.522 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:51:46.974 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:51:57.773 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:51:58.201 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:52:11.447 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:52:11.843 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:52:33.370 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:52:33.822 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:52:47.303 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:52:47.700 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:53:17.202 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:53:17.669 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:53:33.403 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:53:33.931 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:53:50.518 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:53:50.934 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:54:04.620 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:54:05.177 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:54:16.686 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:54:17.138 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
2024-03-23 14:54:31.499 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'au_pv.rules'
2024-03-23 14:54:31.961 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'au_pv.rules', using it anyway:
Constant condition is always false.
The I did the same with a JRuby file and after the 11th save i got the first timeout-message:
2024-03-23 15:40:20.284 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:40:55.031 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:41:19.445 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:41:55.356 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:42:28.603 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:43:01.496 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:43:35.658 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:44:09.842 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:44:51.034 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:45:31.698 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:46:19.801 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:47:19.002 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:47:22.607 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:48:14.027 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:49:08.360 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:49:30.469 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:50:00.646 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.thing.internal.CommunicationManager@14c2b12' takes more than 5000ms.
2024-03-23 15:50:10.857 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:51:09.509 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:52:37.614 [INFO ] [ort.loader.AbstractScriptFileWatcher] - (Re-)Loading script '/etc/openhab/automation/ruby/glob_zwave_checker.rb'
2024-03-23 15:53:25.898 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:53:37.959 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
2024-03-23 15:53:49.562 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.internal.items.ItemUpdater@1fe3222' takes more than 5000ms.
...
...
...
What I have noticed is that when I am waiting on the page “http://:8080/settings/rules/” with the filter set for the current rule and it takes longer and longer with every save until the JRuby script is available again.
In the beginning it is only about 5 seconds or less. When the first timeout occurs, it is already about 30 seconds. Two “savings” later it takes a very long time (several minutes).
Also it takes longer and longer to open the script for manual execution. After clicking the rule on “http://:8080/settings/rules/” the view changes immediately to a empty frame but then it take some time until I can see the text of the rule (also this time gets longer an longer).
@Duke_Jones are you using a 32-bit OS or a 64-bit one?
How much memory does openhab’s java process use?
What would happen if after two saves, you wait for several minutes and don’t do any more saves. The idea is to let whatever it is to finish executing without adding more tasks to the queue. Does it get back to 5 seconds or less after that?
It’s a 32 bit bullseye image but at some point I switched the kernel to 64 bit.
At the moment openhab uses 1063M. After saving 5 times with 5 minutes in between the last 3 saves, it has remained the same.
I’ll have to see when I can do a longer test series. But even if it turns out that I have to wait a few minutes between each save, this is of course quite a hindrance.
Soon I wanted to completely rebuild my system on 64bit with a bookworm image.
I’ve definitely seen this message occasionally, and you’re right that I have to reboot openHAB when it happens. But I’ve usually just pinned it on an extremely complex openHAB configuration (thousands of items, many hundreds of things, and a ton of rules). I’ve been meaning to deep dive into it sometime, but it hasn’t been annoying enough yet to do so.
@Duke_Jones try adding -Xmx2560m or -Xmx3072m to your java options and see if the problem goes away. I suspect you’re hitting a java heap size limit.
My experiments on a 64-bit OS (Ubuntu, openhab running inside docker) with 128GB physical RAM
-Xmx1024m and my openhab won’t finish loading. It only managed to load a few (less than 10?) ruby scripts
-Xmx2560m is the minimum for my system to load but after saving a ruby script several times (triggering a script reload), I can see the same warning that you had.
-Xmx3072m I still see the problem after doing about 20 times modify-save cycles
-Xmx4096m no problems even after doing 30+ modify-save cycles. Probably shouldn’t do this on a 4GB machine. You’d need to reserve some RAM for other processes.
Probably to be on the safe side, get an rpi with 8GB and install a 64-bit OS on it, then use -Xmx4096m or higher.
Alternatively, with a 4GB pi, try switching back to a 32-bit kernel. If you still encountered a problem, try -Xmx2048m
I suspect that a 64-bit OS on a 4GB pi would be a bad combination because the 64-bit OS would need/use a lot more RAM than a 32-bit OS would.
Also try to uninstall any unused add-ons (binding, other scripting languages, etc), other unused programs etc to maximise available RAM for Java.
Additional hint: Each ruby file would be loaded in a separate jruby engine. By pooling many rules inside the same file, and have fewer number of files, you’d save a bit of memory.
I tried it with -Xmx2048m and it actually makes a considerable difference. After saving 25 times, the system still responded more quickly than with the old setting (-Xmx768m) after the first save.
In the meantime, my 8GB Raspberries are on their way, so I will have double the memory available in the next few days.
