Nothing external if I’m assuming bindings are considered internal. The binding I suspect is the cause is the xiaomi binding. It communicates with the gateway which then uses, I believe, zwave to talk to the devices. Perhaps that’s taking 5 seconds?
It could take that long but it wouldn’t be a blocking action so it wouldn’t hold on to a Timer body or cron/Astro triggered Rule for all that time. It would immediately return and the binding would process the command in the background.
From Rules your interaction with the binding is done via commands sent to Items. That command gets put on the event bus and sendCommand immediately returns. No waiting.
To solve this, you need to find what could possibly be taking five seconds to complete in Timer bodies, cron triggered Rules or Astro triggered Rules. There may be other bindings that use Quartz to schedule future events as well.
Nothing 
No (long) sleeps, no endless loops. Some http calls but they all 2s timeout. All timers either toggle a switch which might be turning on the power etc or it inturn fires another rule. Anything else is done via timers.
This error and associated exception only happen when I execute the rule with cron. Trigger by a switch which is toggled from api via OS cron? Never errors.
Triyger it via switch toggled from the rule triggered by cron? Errors will appear.
I’m now running from OS cron again. Will seen after a week.
May we see the (recent version of) the cron rule that messes up, and the Item triggered version that doesn’t?
Sure, both version below
rule "CalcLastMotionAgo"
when
// Time cron "0 0/1 * 1/1 * ? *" //every minute
// or
Item RecalcMotion changed to ON
then
logWarn("Calc Last Motion ago", "Calculating last-motion")
MotionLastCalced.sendCommand(now.toString)
g_LastMotionAgo?.allMembers.forEach[item |
if (item === null){
logWarn("Calc Last Motion ago", "Item item was null. Very odd")
return;
}
// val iName = item.name
// if (item.state == NULL){
// logWarn("Calc Last Motion ago", "Item " + iName + " was NULL. item: " + item.name)
// //sendCommand(iName.replace("_LastMotion", "_MotionMinutesAgo"), "0")
// item.sendCommand(now.toString)
// return;
// }
val motionAgo = (now.millis - (item.state as DateTimeType).zonedDateTime.toInstant.toEpochMilli) / 1000 / 60
sendCommand(iName.replace("_LastMotion", "_MotionMinutesAgo"), motionAgo.toString)
]
RecalcMotion.sendCommand(OFF)
end
Here are the logs from yesterday during the day
2019-08-11 14:49:29.060 [INFO ] [ome.model.script.rooms.climate.rules] - evohome_Wetroom_Temperature_Warmup is not on as we're not controlling. We're not interfering
2019-08-11 14:54:49.859 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 14:55:44.878 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 14:56:44.892 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 14:57:44.931 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 14:58:44.915 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:00:00.039 [INFO ] [el.script.Utility.Count - Clear Hour] - Clearing UtilityElectricUnitsH
2019-08-11 15:00:00.035 [WARN ] [pse.smarthome.model.script.Heartbeat] - ping
2019-08-11 14:59:44.947 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:00:33.978 [INFO ] [el.script.Utility.Count - Clear Hour] - Clearing UtilityGasUnitsH
2019-08-11 15:01:24.961 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness to 100.
2019-08-11 15:03:25.496 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness back to 10
2019-08-11 15:05:25.377 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness to 100.
2019-08-11 15:07:25.670 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness back to 10
2019-08-11 15:07:05.145 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:08:30.187 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:09:24.442 [INFO ] [eclipse.smarthome.model.script.Entry] - Front door was opened
2019-08-11 15:09:30.970 [INFO ] [eclipse.smarthome.model.script.Entry] - Front door was closed
2019-08-11 15:09:30.245 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:11:30.219 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:12:30.266 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:13:30.222 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
2019-08-11 15:14:30.288 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
------snip
2019-08-11 21:14:17.540 [WARN ] [.model.script.Blinds Action list Add] - Key FrontRoomRight already in list. Count is now 8
2019-08-11 21:14:17.512 [ERROR] [org.quartz.simpl.SimpleThreadPool ] - Worker thread was interrupt()'ed.
java.lang.InterruptedException: null
at java.lang.Object.wait(Native Method) ~[?:?]
at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
2019-08-11 21:14:00.040 [WARN ] [e.model.script.Blind Add Action Item] - FrontRoomRight|BlindsMotorControl_FrontRoomRight|DOWN|100
2019-08-11 21:13:17.625 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@155fd69' takes more than 5000ms.
There are a lot of them in the “snip” section.
Last night, whilst we were talking, I changed it back to the OS-based cron option and not a single issue since.
This runs every minute
wget -q --spider http://homeauto.home:8080/classicui/CMD?RecalcMotion=ON
Now, if I have another cron-based rule and toggle the switch to on I get the same errors in the log and eventually quartz dies leaving OH “pointless” 
note the ping line in the logs. This is a cron rule which simply writes the word ping to the logs. It’s what I use to manually see if quartz has died.
No other cron jobs in OH have this problem. Just this one.
items
DateTime Hallway_MotionSensor_LastMotion "[%1$tY-%1$tm-%1$td %1$tH:%1$tM]" <clock-on> (g_LastMotionAgo) { channel="mihome:sensor_motion_aq2:158d0001e5266c:lastMotion" }
things
Thing mihome:sensor_motion_aq2:158d0001e5266c "Sensor - Motion - Hallway" [itemId="158d0001e5266c"] //backdoor door
So, it loops over all the items from the Xiaomi sensors, gets the datetime value from them, works out the difference to now in minutes and then pushes that into the associated item.
My suspicion is there is some sort of deadlock between this code putting something on the bus and the binding polling or writing to the item. I’ve read the binding code and can see where it does this but a) don’t understand enough about java and the framework to see if there are any issues and b) that theory still conflicts with my understanding of what framework does and with what @rlkoshak said above. It should not deadlock.
*apologies to OP for the hijack but perhaps this actually helps as it seems I am not alone
I have an every minute rule using
Time cron "0 0/1 * * * ?" // each minute
which of course shouldn’t matter.
It may be that the crucial difference between cron trigger and external periodic trigger is synchronizing with other internal processes.
I would imagine, for example, some of these items are persisted. I’d be considering if the event bus logjam has an underlying cause of bulk storage I/O logjam.
Some http calls but they all 2s timeout.
I have a vague recollection that the timeout may not be followed in the sendHttp*Request commands. It might be worth while adding some logging before and after those calls to verify that the timeout is actually working.
Crispin:
Anything else is done via timers.
It’s the anything else done via timers that is relevant right now.
Crispin:
This error and associated exception only happen when I execute the rule with cron.
But the error could be caused by other Timers blocking the cron trigger’s Rule’s ability to run within five seconds of being triggered. The error isn’t very clear that it’s complaining that a Timer or cron triggered rule took more than five seconds to complete or that it took more than five seconds for a thread to free up so it could execute the Rule.
Crispin:
Sure, both version below
There is nothing in that Rule that should take a long time to run, unless you have thousands of members in g_LastMotionAgo. So perhaps the real problem is the latter of the two described above, it’s taking longer than five seconds for the Rule to start executing because all the threads are currently in use for five seconds.
Crispin:
not a single issue since.
This runs every minute
That makes sense because with the OS cron trigger, the Rule is running out of the rules thread pool, not the Quartz thread pool.
The more I look at it the less I think it’s this Rule that is causing the problem. Somewhere else you have a Timer body or cron/Astro triggered Rule that is taking longer than expected or crashing in a way that doesn’t return the thread to the Quartz thread pool. Then when this Rule tries to run, it takes more than five seconds to start running and OH sees that delay and throws an error.
Crispin:
My suspicion is there is some sort of deadlock between this code putting something on the bus and the binding polling or writing to the item.
That all happens in the background using other OH thread pools and would not impact the Quartz thread pool. When you sendCommand to an Item the sendCommand doesn’t block until the binding processes it. It immediately returns once the command is placed on the Event Bus which should take mere microseconds.
rossko57:
I would imagine, for example, some of these items are persisted. I’d be considering if the event bus logjam has an underlying cause of bulk storage I/O logjam.
That’s an interesting theory. You can see if that’s the case by adding logging statements before and after the sendCommand/postUpdates and checking the timestamps. That will also show that anything going on in the binding is also not blocking the Rule from running.
Interesting. I have many every-minute cron rules which fire and don’t cause a problem.
I am certain, but checking again tonight, I did have a rule which used cron to trigger the switch and the switch triggered the motion rule. This also failed. Why would it fail?
While I am sure, I am setting this up again tonight and will let it run overnight.
No, the group has 5 or 6 items in it. It’s not large. To @rossko57 point, none of the items are persisted. They’re datetime if that feeds any thought process.
I have loads of cron rules which work without a problem. I have one which runs every 30 minutes and writes out “ping”. I can certainly make it move frequent to try and exacerbate the problem.
I also have a rule, cron based, which runs every 5 minutes to check the position of the blinds. It does not falter until quartz totally gives up the ghost.
This “we’ve” spoken about before. When this error happens the log entries are all out of sequence.
See here: Help understanding quartz crashing - "Worker thread was interrupt()'ed."
As a snippet, look at the logs here:
1 2019-01-05 10:48:14.674 [INFO ] [home.model.script.Motion - resetting] - Motion from - Kitchen_MotionSensor - resetting to zero
2 2019-01-05 10:48:12.596 [WARN ] [me.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.eclipse.smarthome.io.monitor.internal.EventLogger@1e2e736' takes more than 5000ms.
3 2019-01-05 10:47:37.641 [INFO ] [home.model.script.Motion - resetting] - Motion from - Hallway_MotionSensor - resetting to zero
4 2019-01-05 10:47:27.061 [WARN ] [me.model.script.Motion - Auto Lights] - Bathroom_MotionSensor caused auto-lights - state:OFF
5 2019-01-05 10:47:17.012 [WARN ] [l.script.controls.tablet.state.rules] - Brighten Screen - Setting brightness to 100.
6 2019-01-05 10:52:12.890 [WARN ] [me.model.script.Motion - Auto Lights] - Room: Bathroom
7 2019-01-05 10:49:42.950 [DEBUG] [rg.quartz.core.QuartzSchedulerThread] - batch acquisition of 1 triggers
8 2019-01-05 10:49:42.949 [ERROR] [org.quartz.simpl.SimpleThreadPool ] - Worker thread was interrupt()'ed.
9 java.lang.InterruptedException: null
10 at java.lang.Object.wait(Native Method) ~[?:?]
11 at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
12 2019-01-05 10:49:12.610 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Main], State[726]
13 2019-01-05 10:49:12.610 [DEBUG] [org.quartz.core.JobRunShell ] - Calling execute on job DEFAULT.state.motion.lastmotion.rules#Calc Last Motion ago#0 0/1 * 1/1 * ? *
14 2019-01-05 10:55:12.954 [INFO ] [htwaverf.internal.LightwaveRfBinding] - Update from LightwaveRf ItemName[Power_Solar_prxy], State[144]
15 2019-01-05 10:54:42.934 [ERROR] [org.quartz.simpl.SimpleThreadPool ] - Worker thread was interrupt()'ed.
16 java.lang.InterruptedException: null
17 at java.lang.Object.wait(Native Method) ~[?:?]
18 at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:568) [107:org.eclipse.smarthome.core.scheduler:0.10.0.oh240]
19
See how out of sequence the log entries are?
That “resetting” entry is the binding triggering a motion. It then set a the motionago item for that room back to zero.
So, actually, you have two rules here: 1) counting the minutes up. When it uses an item with that binding it fails and 2) a rule which fires and then resets the counter back to zero.
Two rules and they both fail, binding in the middle.
Things to try tonight -
- Set up another minute-based rule in the same rules file to test with.
- Disable the OS cron and revert to a cron-based rule which toggles the proxy item and check for failures.
- to do tomorrow - remove the binding from the items. You’re theories will be proved either way if I do that. If it no longer fails then it’s confirmed to be a item+binding issue. If it still fails, then it is a rule / item / threading issue.
- You have lot of cron triggering Rules.
- Let’s assume you have the default number of Quartz threads of 2
- Two of those cron triggered Rules take 10 seconds to complete.
- While those two Rules are running, let’s say 3 seconds in, another cron triggered Rule tries to execute.
- It takes more than five seconds for that third cron triggered Rule to start running and OH throws an exception.
It doesn’t matter what that third Rules actually does. It never got a chance to do it because those first two cron triggered Rules are hogging all the execution threads.
It can be even worse if for some reason those first two cron triggered Rules never return because of some bug or error that occurred.
The fact that you have “many every-minute cron rules” is a code smell. You should not have many. More than two would be too many, and even for the two you would need to make sure they don’t execute at exactly the same time (e.g.one uses 0 * * * * * ? * and the other uses 30 * * * * * ? *) so they don’t execute at the same time.
If you have lots of cron triggered Rules trying to trigger at the same time, I can totally see how you might break Quartz itself which might be the root cause of the problem. I can also see how you might end up starving a Rule or two because it isn’t clear whether Quartz uses a FIFO queue for those Rules that are waiting to get a thread.
Only to further confirm that the problem isn’t in this Rule, it’s before this Rule. The problem is your other cron triggered Rules (and Timers and Astro triggered Rules) are starving this Rule. It takes more than five seconds for the Rule to get an execution thread so it get’s errored out. That error may “break” Quartz preventing it from running any further Rules, or something may have broken Quartz before that point. I don’t think it is well tested error code as almost no one has encountered this problem with cron Rules. Most users don’t have that many and they rarely try to run them at the same time.
I’m convinced now that “loads of cron rules” is the problem.
I don’t know what a proper sequence for those log entries would be. Remember, each event in OH is processed in parallel. If you have two events being processed at the same time then the log entries for those events will be interleaved.
3 I already know will not do anything. The binding doesn’t block Rules. The binding can take half an hour to respond to an event but the sendCommand will return in milliseconds.
Well yes, we might expect jumbled log messages with this going on. I’ll hazard a guess your system is fairly stressed and can be tipped into a logjam in various ways.
My thought about persistence was more about strategies like everyMinute invoking a workload spike, which will coincide with this rules cron trigger. They’re all running at the same whole minute and no seconds, not staggered across the clockface.
Humm, now we got lots of rules and possibly system services all lined up at the top of the minute.
I’ve got to wonder why lots of cron rules are needed in openHAB.
Time cron "30 * * * * ? *" // each minute at second 30
would run your suspect rule every minute but staggered from other minute based happenings
I’ll go through and catalogue the rules I have running and when they actually execute. It may well be that I have a number of clashes.
I did change the Quartz threads to 50 (I know! ) to absorb the crashes for longer while I worked this out. Would the fact that I have that many threads go against the thought that it’s too many cron jobs running at the same time? At least for Quartz. Yes, concurrent rules might be a problem. I will try and understand those too as I have some which run quite frequently due to power consumption fluctuations in the house.
This, however, is interesting. Last night I did option 3 first (I know I know )
I put the cron back in to the rule trigger. I commented out the switch item change and left the OS cron as-is.
I then also commented out the channel link for the item in the group. i.e. the one it loops over to get the last time motion was detected.
The rule ran all night, every minute as it should, without one crash. The safety “ping” rule is also running happily which suggests quarts is still alive.
I can see the MotionAgo values are increasing because the rule is counting up and the last-motion datetime item is not being updated by the binding.
Does this contradict with your thought of “too many rules executing”?
Without the binding linked to the item which is in a group being enumerated, the rule, and quartz, never fail.
I’ll try option 2 this evening and see if that reverts to failing overnight.
@rossko57
Regarding the persistence etc, I have mysql logging and mapdb. The most frequent timed one is every 5 minutes. I’ll change that to 15 seconds past to spread that around. The others, mysql (and one mapdb) is quite chatty as it’s reading power values of the house and changes every 30 seconds.
Question:
Could it be that the binding is breaking the model by trying to access the variables directly and not put the changes “on the bus” where the normal framework takes over?
I have other rules which enumerate items in groups and change their values and nothing ever faults there. It’s always just this guy…
Thanks for the help
It’s not really clear if these
Dispatching event ... EventLogger@155fd69' takes more than 5000ms.
warnings actually go away when you change the “problem rule”.
A closer look at your “problem rule”.
So far as I can see, there’s only circumstantial evidence linking this rule to the InterruptedException: null errors i.e. they only happen sometimes when this rule is triggered a particular way, but no direct link in any message?
Being picky, your OS+Item based external trigger is command based. Rule trigger is state changed.
Should the OH event bus be jammed when your command comes in, the rule will not trigger until after the command gets on the bus, and then autoupdate processes it into an update, and the update gets put on the bus.
In other words, the external trigger will fire the rule after the event bus has got moving again, the rule will effectively be queued.
All I’m doing is looking for the reason why the rule should have different consequences depending on trigger source.
What is the purpose of the ? here, could that be hiding/suppressing a clue.
Only if the problem is caused by running out of threads. But if the problem is a lack of resources because you have a ton of stuff trying to be done on the first second of a minute than it will only add to the amount of work that is trying to be done all at once.
It is impossible for the binding to access the variable directly.
when I change the trigger type - yes, they go away.
I have another rule - a new one I just finished - which checks to see that that blinds are open. It now runs every minute, is running without a hitch. It’s cron-triggered.
You’re correct. It is circumstantial. However, it is repeatable and consistent. So much so that I suggest it is this rule/trigger-type/binding.
An interesting thought. How does this get affected by the other rules?
It will not error if the group is NULL
Is there a way OH can tell us how busy it is internally? Some sort of debug stats or something to show?
I look at glances and see this:
The CPU bounces around but never high. Obviously this ,ay not be a true representation of the internal state of OH hence the question above.
What rules do I have?
Cron based:
\\homeauto.home\openHAB-conf\rules\blinds.checkactioned.rules (1 hit)
Line 75: or Time cron "0 0/1 * 1/1 * ? *" //every minute
\\homeauto.home\openHAB-conf\rules\cron.garden.pond.rules (3 hits)
Line 4: Time cron "0 0 9 1/1 * ? *" or //9am
Line 5: Time cron "0 0 7 ? * SAT,SUN *" //7am
Line 17: Time cron "0 0 1 1/1 * ? *" //1am
\\homeauto.home\openHAB-conf\rules\cron.garden.pool.rules (2 hits)
Line 4: Time cron "0 0 9 1/1 * ? *" //9am
Line 16: Time cron "0 0 18 1/1 * ? *" //6pm
\\homeauto.home\openHAB-conf\rules\cron.heartbeat.rules (1 hit)
Line 2: when Time cron "0 0/31 * 1/1 * ? *" //every 31 minutes
\\homeauto.home\openHAB-conf\rules\cron.state.climate.autoheat.rules (4 hits)
Line 4: Time cron "0 45 4 ? * MON,TUE,WED,THU,FRI *" //4:45AM Mon-Friday
Line 5: or Time cron "0 0 7 ? * SAT,SUN *" //7AM Sat/Sun
Line 17: Time cron "0 0 8 ? * MON,TUE,WED,THU,FRI *" //8AM Mon-Friday
Line 18: or Time cron "0 0 9 ? * SAT,SUN *" //9AM Sat/Sun
\\homeauto.home\openHAB-conf\rules\cron.utility.fridge.wine.rules (4 hits)
Line 4: Time cron "0 0 21 ? * MON,TUE,WED,THU,SUN *" //Mon-Thu @ 21
Line 5: or Time cron "0 0 23 ? * FRI,SAT *" //Fri/sat @ 22
Line 13: Time cron "0 0 16 ? * MON,TUE,WED,THU *" //Mon-Thu @ 21
Line 14: or Time cron "0 0 11 ? * FRI,SAT,SUN *" //Fri/sat @ 22
\\homeauto.home\openHAB-conf\rules\cron.utility.reset.rules (2 hits)
Line 3: when Time cron "0 0/15 * 1/1 * ? *" //every 15 minutes
Line 22: when Time cron "0 0/15 * 1/1 * ? *" //every 15 minutes
\\homeauto.home\openHAB-conf\rules\speedtest.rules (1 hit)
Line 17: Time cron "0 0 0/6 * * ?" //6am
\\homeauto.home\openHAB-conf\rules\state.climate.home.rules (2 hits)
Line 63: when Time cron "0 0 16 ? * MON,TUE,WED,THU,FRI *" //4pm daily
Line 81: when Time cron "0 30 23 ? * * *" //23:30 daily
\\homeauto.home\openHAB-conf\rules\state.motion.lastmotion.rules (1 hit)
Line 4: //Time cron "0 0/1 * 1/1 * ? *" //every minute
\\homeauto.home\openHAB-conf\rules\transport.trains.rules (1 hit)
Line 31: Time cron "0 0/10 * 1/1 * ? *" //every 10 minutes
\\homeauto.home\openHAB-conf\rules\trash.rules (1 hit)
Line 24: when Time cron "0 0 3 ? * * *" //3am
\\homeauto.home\openHAB-conf\rules\utility.clear.counters.rules (5 hits)
Line 2: when Time cron "0 0 0/1 1/1 * ? *" //every hour
Line 16: when Time cron "0 0 0 1/1 * ? *" //12am
Line 30: when Time cron "0 0 0 ? * SUN *" //every sunday
Line 43: when Time cron "0 0 0 1 1/1 ? *" //every month
Line 56: when Time cron "0 0 0 1 1 ? *" //every year
\\homeauto.home\openHAB-conf\rules\utility.electrical.excess.rules (1 hit)
Line 42: when Time cron "0 0 0 1/1 * ? *" //12am
Only two or three, including the offending one, which are every minute.
What I do have, which may be adding to load, is a few rules which calc stuff based on power fluctuations. These fire quite a lot. See the events log for a smell of that. Thoughts?
2019-08-13 17:27:08.226 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from -0.03 to -0.06
2019-08-13 17:27:08.234 [vent.ItemStateChangedEvent] - shed_load_current changed from -3.08 to -2.37
2019-08-13 17:27:08.238 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.30 to -0.33
2019-08-13 17:27:08.243 [vent.ItemStateChangedEvent] - shed_battery_current changed from 2.75 to 1.98
2019-08-13 17:27:08.747 [vent.ItemStateChangedEvent] - ControlsKitchenConnectedTime changed from 2019-08-13T17:26:35.000+0100 to 2019-08-13T17:27:05.000+0100
2019-08-13 17:27:09.073 [vent.ItemStateChangedEvent] - utility_boiler_heating_flow changed from 24.00 to 24.50
2019-08-13 17:27:09.824 [vent.ItemStateChangedEvent] - SunElevation changed from 26.94021049438947 to 26.787848602559045
2019-08-13 17:27:09.848 [ome.event.ItemCommandEvent] - Item 'BlindsClosingAt' received command 1900-01-01T20:57:00.000+0000
2019-08-13 17:27:09.877 [ome.event.ItemCommandEvent] - Item 'BlindsOpeningAt' received command 1900-01-01T07:00:00.000+0000
2019-08-13 17:27:10.071 [vent.ItemStateChangedEvent] - utility_boiler_heating_flow changed from 24.50 to 24.00
2019-08-13 17:27:10.702 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from OFF to ON
2019-08-13 17:27:10.711 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulse' received command OFF
2019-08-13 17:27:10.725 [ome.event.ItemCommandEvent] - Item 'UtilityElectricLastPulse' received command 2019-08-13T17:27:10.709+0100
2019-08-13 17:27:10.734 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from ON to OFF
2019-08-13 17:27:10.738 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUnitsTotal' received command 71.652
2019-08-13 17:27:10.745 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulseTick' received command 1
2019-08-13 17:27:10.758 [vent.ItemStateChangedEvent] - UtilityElectricLastPulse changed from 2019-08-13T17:27:00.641+0100 to 2019-08-13T17:27:10.709+0100
2019-08-13 17:27:10.763 [vent.ItemStateChangedEvent] - UtilityElectricUnitsTotal changed from 71.651 to 71.652
2019-08-13 17:27:10.789 [ome.event.ItemCommandEvent] - Item 'UtilityElectricKWH10m' received command 0.30000000
2019-08-13 17:27:11.295 [vent.ItemStateChangedEvent] - utility_dishwasher_current changed from 0.007 to 0.000
2019-08-13 17:27:11.350 [vent.ItemStateChangedEvent] - utility_dishwasher_power changed from 1 to 0
2019-08-13 17:27:11.354 [GroupItemStateChangedEvent] - g_Appliances_Power_Sum changed from 79.0 to 78.0 through utility_dishwasher_power
2019-08-13 17:27:11.356 [GroupItemStateChangedEvent] - g_Utility_Power_Sum changed from 79 to 78 through utility_dishwasher_power
2019-08-13 17:27:11.359 [GroupItemStateChangedEvent] - g_utility_electric_safety_exclude changed from 79.0 to 78.0 through utility_dishwasher_power
2019-08-13 17:27:11.950 [ome.event.ItemCommandEvent] - Item 'RecalcMotion' received command OFF
2019-08-13 17:27:11.956 [vent.ItemStateChangedEvent] - RecalcMotion changed from ON to OFF
2019-08-13 17:27:12.229 [vent.ItemStateChangedEvent] - Fridge_Main_Xiaomi_Temperature changed from 6.09 to 6.6
2019-08-13 17:27:12.252 [vent.ItemStateChangedEvent] - Fridge_Main_Xiaomi_Humidity changed from 83.14 to 79.3
2019-08-13 17:27:12.369 [vent.ItemStateChangedEvent] - evohome_Kitchen_Temperature changed from 25.0 to 25.5
2019-08-13 17:27:12.372 [GroupItemStateChangedEvent] - g_TempDownstairs changed from 21.6 to 21.8 through evohome_Kitchen_Temperature
2019-08-13 17:27:13.645 [vent.ItemStateChangedEvent] - shed_system_voltage changed from 5208 to 5226
2019-08-13 17:27:13.664 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.00 to 0.01
2019-08-13 17:27:13.671 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from -0.06 to -0.03
2019-08-13 17:27:13.676 [vent.ItemStateChangedEvent] - shed_load_current changed from -2.37 to -1.72
2019-08-13 17:27:13.680 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.33 to -0.31
2019-08-13 17:27:13.684 [vent.ItemStateChangedEvent] - shed_battery_current changed from 1.98 to 1.38
2019-08-13 17:27:14.717 [vent.ItemStateChangedEvent] - Proxy_WazeTravelTime_HarrodsKB changed from 61.03 to 65.27
2019-08-13 17:27:14.724 [ome.event.ItemCommandEvent] - Item 'WazeTravelTime_HarrodsKB' received command 65.27
2019-08-13 17:27:14.727 [vent.ItemStateChangedEvent] - WazeTravelTime_HarrodsKB changed from 61.03 to 65.27
2019-08-13 17:27:17.294 [vent.ItemStateChangedEvent] - Power_Solar_prxy changed from 236 to 230
2019-08-13 17:27:17.312 [vent.ItemStateChangedEvent] - Power_Solar changed from 167 to 161
2019-08-13 17:27:17.321 [ome.event.ItemCommandEvent] - Item 'Power_Grid' received command 391
2019-08-13 17:27:17.334 [vent.ItemStateChangedEvent] - Power_Grid changed from 385 to 391
2019-08-13 17:27:17.339 [ome.event.ItemCommandEvent] - Item 'PowerIsBelowZero' received command OFF
2019-08-13 17:27:17.347 [ome.event.ItemCommandEvent] - Item 'PowerLastExcessMillis' received command 1565713637338
2019-08-13 17:27:17.353 [vent.ItemStateChangedEvent] - PowerLastExcessMillis changed from 1565713625038 to 1565713637338
2019-08-13 17:27:18.907 [vent.ItemStateChangedEvent] - LocalServer_Cpu_Load changed from 7.0 to 8.1
2019-08-13 17:27:18.916 [vent.ItemStateChangedEvent] - LocalServer_Memory_Used changed from 47.2 to 47.1
2019-08-13 17:27:18.922 [vent.ItemStateChangedEvent] - utility_db_lights_downstairs_rear_current changed from 0.239 to 0.240
2019-08-13 17:27:19.143 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.01 to 0.06
2019-08-13 17:27:19.153 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from -0.03 to 0.01
2019-08-13 17:27:19.157 [vent.ItemStateChangedEvent] - shed_battery_voltage changed from 14.40 to 14.41
2019-08-13 17:27:19.162 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.31 to -0.27
2019-08-13 17:27:19.166 [vent.ItemStateChangedEvent] - shed_battery_current changed from 1.38 to 1.46
2019-08-13 17:27:19.958 [vent.ItemStateChangedEvent] - Power_House_prxy changed from 621 to 611
2019-08-13 17:27:19.987 [vent.ItemStateChangedEvent] - Power_House changed from 552 to 542
2019-08-13 17:27:20.000 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUsageState2' received command 542
2019-08-13 17:27:20.017 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUsageNetState2' received command 464.0
2019-08-13 17:27:20.021 [ome.event.ItemCommandEvent] - Item 'Power_Grid' received command 381
2019-08-13 17:27:20.026 [vent.ItemStateChangedEvent] - UtilityElectricUsageState2 changed from 552 to 542
2019-08-13 17:27:20.031 [vent.ItemStateChangedEvent] - UtilityElectricUsageNetState2 changed from 473.0 to 464.0
2019-08-13 17:27:20.037 [vent.ItemStateChangedEvent] - Power_Grid changed from 391 to 381
2019-08-13 17:27:20.042 [ome.event.ItemCommandEvent] - Item 'PowerIsBelowZero' received command OFF
2019-08-13 17:27:20.046 [ome.event.ItemCommandEvent] - Item 'PowerLastExcessMillis' received command 1565713640041
2019-08-13 17:27:20.052 [vent.ItemStateChangedEvent] - PowerLastExcessMillis changed from 1565713637338 to 1565713640041
2019-08-13 17:27:20.203 [vent.ItemStateChangedEvent] - utility_boiler_hot_water changed from 35.00 to 34.50
2019-08-13 17:27:20.804 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from OFF to ON
2019-08-13 17:27:20.812 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulse' received command OFF
2019-08-13 17:27:20.819 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from ON to OFF
2019-08-13 17:27:20.827 [ome.event.ItemCommandEvent] - Item 'UtilityElectricLastPulse' received command 2019-08-13T17:27:20.810+0100
2019-08-13 17:27:20.838 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUnitsTotal' received command 71.653
2019-08-13 17:27:20.844 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulseTick' received command 1
2019-08-13 17:27:20.854 [vent.ItemStateChangedEvent] - UtilityElectricLastPulse changed from 2019-08-13T17:27:10.709+0100 to 2019-08-13T17:27:20.810+0100
2019-08-13 17:27:20.859 [vent.ItemStateChangedEvent] - UtilityElectricUnitsTotal changed from 71.652 to 71.653
2019-08-13 17:27:20.902 [ome.event.ItemCommandEvent] - Item 'UtilityElectricKWH10m' received command 0.30000000
2019-08-13 17:27:24.592 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.06 to 0.04
2019-08-13 17:27:24.596 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from 0.01 to -0.02
2019-08-13 17:27:24.601 [vent.ItemStateChangedEvent] - shed_load_current changed from -1.72 to -1.23
2019-08-13 17:27:24.605 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.27 to -0.29
2019-08-13 17:27:24.609 [vent.ItemStateChangedEvent] - shed_battery_current changed from 1.46 to 0.92
2019-08-13 17:27:24.688 [vent.ItemStateChangedEvent] - utility_kitchen_fridge_main_current changed from 0.014 to 0.021
2019-08-13 17:27:27.672 [vent.ItemStateChangedEvent] - evohome_Kitchen_Temperature changed from 25.5 to 25.0
2019-08-13 17:27:27.675 [GroupItemStateChangedEvent] - g_TempDownstairs changed from 21.8 to 21.6 through evohome_Kitchen_Temperature
2019-08-13 17:27:28.395 [vent.ItemStateChangedEvent] - DenisePhoneUptime changed from 7565 to 7605
2019-08-13 17:27:28.413 [vent.ItemStateChangedEvent] - DenisePhoneLastSeen changed from 2019-08-13T17:26:46.000+0100 to 2019-08-13T17:27:26.000+0100
2019-08-13 17:27:28.418 [vent.ItemStateChangedEvent] - DenisePhoneRSSI changed from 39 to 40
2019-08-13 17:27:29.018 [vent.ItemStateChangedEvent] - utility_boiler_heating_flow changed from 24.00 to 24.50
2019-08-13 17:27:29.092 [vent.ItemStateChangedEvent] - utility_boiler_heating_flow changed from 24.50 to 24.00
2019-08-13 17:27:30.034 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.04 to 0.05
2019-08-13 17:27:30.043 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from -0.02 to 0.01
2019-08-13 17:27:30.048 [vent.ItemStateChangedEvent] - shed_load_current changed from -1.23 to -1.49
2019-08-13 17:27:30.053 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.29 to -0.25
2019-08-13 17:27:30.057 [vent.ItemStateChangedEvent] - shed_battery_current changed from 0.92 to 1.25
2019-08-13 17:27:30.860 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from OFF to ON
2019-08-13 17:27:30.873 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulse' received command OFF
2019-08-13 17:27:30.882 [ome.event.ItemCommandEvent] - Item 'UtilityElectricLastPulse' received command 2019-08-13T17:27:30.872+0100
2019-08-13 17:27:30.895 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from ON to OFF
2019-08-13 17:27:30.905 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUnitsTotal' received command 71.654
2019-08-13 17:27:30.912 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulseTick' received command 1
2019-08-13 17:27:30.921 [vent.ItemStateChangedEvent] - UtilityElectricLastPulse changed from 2019-08-13T17:27:20.810+0100 to 2019-08-13T17:27:30.872+0100
2019-08-13 17:27:30.927 [vent.ItemStateChangedEvent] - UtilityElectricUnitsTotal changed from 71.653 to 71.654
2019-08-13 17:27:30.958 [ome.event.ItemCommandEvent] - Item 'UtilityElectricKWH10m' received command 0.30000000
2019-08-13 17:27:32.373 [vent.ItemStateChangedEvent] - utility_boiler_cold_water changed from 19.50 to 19.00
2019-08-13 17:27:32.406 [vent.ItemStateChangedEvent] - Power_Solar_prxy changed from 230 to 227
2019-08-13 17:27:32.414 [vent.ItemStateChangedEvent] - Power_Solar changed from 161 to 158
2019-08-13 17:27:32.431 [ome.event.ItemCommandEvent] - Item 'Power_Grid' received command 384
2019-08-13 17:27:32.443 [vent.ItemStateChangedEvent] - Power_Grid changed from 381 to 384
2019-08-13 17:27:32.462 [ome.event.ItemCommandEvent] - Item 'PowerIsBelowZero' received command OFF
2019-08-13 17:27:32.468 [ome.event.ItemCommandEvent] - Item 'PowerLastExcessMillis' received command 1565713652457
2019-08-13 17:27:32.478 [vent.ItemStateChangedEvent] - PowerLastExcessMillis changed from 1565713640041 to 1565713652457
2019-08-13 17:27:33.378 [vent.ItemStateChangedEvent] - utility_boiler_cold_water changed from 19.00 to 19.50
2019-08-13 17:27:34.649 [vent.ItemStateChangedEvent] - server_son_main_current changed from 0.561 to 0.558
2019-08-13 17:27:34.957 [vent.ItemStateChangedEvent] - Power_House_prxy changed from 611 to 614
2019-08-13 17:27:34.980 [vent.ItemStateChangedEvent] - Power_House changed from 542 to 545
2019-08-13 17:27:34.991 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUsageState2' received command 545
2019-08-13 17:27:35.002 [ome.event.ItemCommandEvent] - Item 'Power_Grid' received command 387
2019-08-13 17:27:35.011 [vent.ItemStateChangedEvent] - UtilityElectricUsageState2 changed from 542 to 545
2019-08-13 17:27:35.019 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUsageNetState2' received command 467.0
2019-08-13 17:27:35.024 [vent.ItemStateChangedEvent] - Power_Grid changed from 384 to 387
2019-08-13 17:27:35.028 [vent.ItemStateChangedEvent] - UtilityElectricUsageNetState2 changed from 464.0 to 467.0
2019-08-13 17:27:35.031 [ome.event.ItemCommandEvent] - Item 'PowerIsBelowZero' received command OFF
2019-08-13 17:27:35.033 [ome.event.ItemCommandEvent] - Item 'PowerLastExcessMillis' received command 1565713655029
2019-08-13 17:27:35.037 [vent.ItemStateChangedEvent] - PowerLastExcessMillis changed from 1565713652457 to 1565713655029
2019-08-13 17:27:35.461 [vent.ItemStateChangedEvent] - shed_system_voltage changed from 5226 to 5222
2019-08-13 17:27:35.473 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.05 to 0.04
2019-08-13 17:27:35.479 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from 0.01 to 0.00
2019-08-13 17:27:35.482 [vent.ItemStateChangedEvent] - shed_load_current changed from -1.49 to -0.87
2019-08-13 17:27:35.485 [vent.ItemStateChangedEvent] - shed_battery_current changed from 1.25 to 0.62
2019-08-13 17:27:37.449 [vent.ItemStateChangedEvent] - utility_boiler_current changed from 0.018 to 0.017
2019-08-13 17:27:38.743 [vent.ItemStateChangedEvent] - ControlsKitchenConnectedTime changed from 2019-08-13T17:27:05.000+0100 to 2019-08-13T17:27:35.000+0100
2019-08-13 17:27:38.806 [vent.ItemStateChangedEvent] - ControlsHallwayConnectedTime changed from 2019-08-13T17:26:38.000+0100 to 2019-08-13T17:27:38.000+0100
2019-08-13 17:27:39.278 [vent.ItemStateChangedEvent] - utility_kitchen_fridge_wine_current changed from 0.487 to 0.489
2019-08-13 17:27:39.328 [vent.ItemStateChangedEvent] - utility_kitchen_fridge_wine_voltage changed from 242 to 240
2019-08-13 17:27:39.330 [GroupItemStateChangedEvent] - g_utility_electric_safety_exclude changed from 78.0 to 79.0 through utility_kitchen_fridge_wine_power
2019-08-13 17:27:39.332 [GroupItemStateChangedEvent] - g_Appliances_Power_Sum changed from 78.0 to 79.0 through utility_kitchen_fridge_wine_power
2019-08-13 17:27:39.335 [vent.ItemStateChangedEvent] - utility_kitchen_fridge_wine_power changed from 75 to 76
2019-08-13 17:27:39.337 [GroupItemStateChangedEvent] - g_Utility_Power_Sum changed from 78 to 79 through utility_kitchen_fridge_wine_power
2019-08-13 17:27:39.340 [vent.ItemStateChangedEvent] - utility_kitchen_fridge_wine_reactive changed from 90 to 89
2019-08-13 17:27:40.950 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.04 to 0.03
2019-08-13 17:27:40.955 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from 0.00 to -0.04
2019-08-13 17:27:40.961 [vent.ItemStateChangedEvent] - shed_load_current changed from -0.87 to 1.01
2019-08-13 17:27:40.966 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.25 to -0.27
2019-08-13 17:27:40.970 [vent.ItemStateChangedEvent] - shed_battery_current changed from 0.62 to -1.32
2019-08-13 17:27:40.974 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from OFF to ON
2019-08-13 17:27:40.998 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulse' received command OFF
2019-08-13 17:27:41.011 [ome.event.ItemCommandEvent] - Item 'UtilityElectricLastPulse' received command 2019-08-13T17:27:40.997+0100
2019-08-13 17:27:41.019 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from ON to OFF
2019-08-13 17:27:41.023 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUnitsTotal' received command 71.655
2019-08-13 17:27:41.029 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulseTick' received command 1
2019-08-13 17:27:41.039 [vent.ItemStateChangedEvent] - UtilityElectricLastPulse changed from 2019-08-13T17:27:30.872+0100 to 2019-08-13T17:27:40.997+0100
2019-08-13 17:27:41.043 [vent.ItemStateChangedEvent] - UtilityElectricUnitsTotal changed from 71.654 to 71.655
2019-08-13 17:27:41.119 [ome.event.ItemCommandEvent] - Item 'UtilityElectricKWH10m' received command 0.30000000
2019-08-13 17:27:41.325 [vent.ItemStateChangedEvent] - utility_db_lights_downstairs_front_current changed from 0.096 to 0.094
2019-08-13 17:27:41.331 [vent.ItemStateChangedEvent] - utility_db_lights_downstairs_front_voltage changed from 238 to 239
2019-08-13 17:27:42.886 [GroupItemStateChangedEvent] - g_TempDownstairs changed from 21.6 to 21.8 through evohome_Kitchen_Temperature
2019-08-13 17:27:42.892 [vent.ItemStateChangedEvent] - evohome_Kitchen_Temperature changed from 25.0 to 25.5
2019-08-13 17:27:43.127 [vent.ItemStateChangedEvent] - Server_HomeAuto_Latency changed from 20.0 to 8.0
2019-08-13 17:27:44.115 [vent.ItemStateChangedEvent] - Server_NAS_Latency changed from 19.0 to 18.0
2019-08-13 17:27:46.390 [vent.ItemStateChangedEvent] - shed_system_voltage changed from 5222 to 5208
2019-08-13 17:27:46.398 [vent.ItemStateChangedEvent] - shed_solar_current changed from 0.03 to 0.01
2019-08-13 17:27:46.422 [vent.ItemStateChangedEvent] - shed_solar_current_charge changed from -0.04 to -0.08
2019-08-13 17:27:46.428 [vent.ItemStateChangedEvent] - shed_load_current changed from 1.01 to 2.35
2019-08-13 17:27:46.433 [vent.ItemStateChangedEvent] - shed_assist_charger_current changed from -0.27 to -0.34
2019-08-13 17:27:46.440 [vent.ItemStateChangedEvent] - shed_battery_current changed from -1.32 to -2.77
2019-08-13 17:27:46.805 [vent.ItemStateChangedEvent] - Server_Media_Latency changed from 19.0 to 9.0
2019-08-13 17:27:47.495 [vent.ItemStateChangedEvent] - Power_Solar_prxy changed from 227 to 225
2019-08-13 17:27:47.519 [vent.ItemStateChangedEvent] - Power_Solar changed from 158 to 156
2019-08-13 17:27:47.530 [ome.event.ItemCommandEvent] - Item 'Power_Grid' received command 389
2019-08-13 17:27:47.538 [vent.ItemStateChangedEvent] - Power_Grid changed from 387 to 389
2019-08-13 17:27:47.558 [ome.event.ItemCommandEvent] - Item 'PowerIsBelowZero' received command OFF
2019-08-13 17:27:47.562 [ome.event.ItemCommandEvent] - Item 'PowerLastExcessMillis' received command 1565713667557
2019-08-13 17:27:47.575 [vent.ItemStateChangedEvent] - PowerLastExcessMillis changed from 1565713655029 to 1565713667557
2019-08-13 17:27:48.204 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from OFF to ON
2019-08-13 17:27:48.211 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulse' received command OFF
2019-08-13 17:27:48.219 [ome.event.ItemCommandEvent] - Item 'UtilityElectricLastPulse' received command 2019-08-13T17:27:48.210+0100
2019-08-13 17:27:48.223 [vent.ItemStateChangedEvent] - UtilityElectricPulse changed from ON to OFF
2019-08-13 17:27:48.225 [ome.event.ItemCommandEvent] - Item 'UtilityElectricUnitsTotal' received command 71.656
2019-08-13 17:27:48.227 [ome.event.ItemCommandEvent] - Item 'UtilityElectricPulseTick' received command 1
2019-08-13 17:27:48.235 [vent.ItemStateChangedEvent] - UtilityElectricLastPulse changed from 2019-08-13T17:27:40.997+0100 to 2019-08-13T17:27:48.210+0100
2019-08-13 17:27:48.237 [vent.ItemStateChangedEvent] - UtilityElectricUnitsTotal changed from 71.655 to 71.656
2019-08-13 17:27:48.273 [ome.event.ItemCommandEvent] - Item 'UtilityElectricKWH10m' received command 0.30600000
2019-08-13 17:27:48.276 [vent.ItemStateChangedEvent] - UtilityElectricKWH10m changed from 0.30000000 to 0.30600000
2019-08-13 17:27:48.803 [vent.ItemStateChangedEvent] - Frontroom_MotionSensor_Illumination changed from 274 to 263
2019-08-13 17:27:48.926 [vent.ItemStateChangedEvent] - LocalServer_Cpu_Load changed from 8.1 to 6.9
2019-08-13 17:27:48.932 [vent.ItemStateChangedEvent] - LocalServer_Memory_Used changed from 47.1 to 47.2
2019-08-13 17:27:49.224 [vent.ItemStateChangedEvent] - Server_DNS_Latency changed from 19.0 to 23.0
2019-08-13 17:27:49.229 [GroupItemStateChangedEvent] - g_Servers_Latency changed from 19.0 to 23.0 through Server_DNS_Latency
2019-08-13 17:27:49.954 [vent.ItemStateChangedEvent] - Power_House_prxy changed from 614 to 625
2019-08-13 17:27:49.971 [vent.ItemStateChangedEvent] - Power_House changed from 545 to 556
Does the frequency of those events and item updates seem busy? It’s quite a few every second.
An example of a power-based rule:
rule "Count seconds excess electricity"
when Item Power_Grid changed
then
val pwr = Power_Grid.state as Number
if (pwr < 0 && PowerIsBelowZero.state != ON){
PowerIsBelowZero.sendCommand(ON)
}
else if (pwr > 0){
try{
if (PowerIsBelowZero.state == ON && PowerLastExcessMillis.state != NULL){//we used to be below zero, now we are not. Calc time and add to original number
//logWarn("DDDD", "Is above zero and switch was set.")
val Number lastAboveZero = PowerLastExcessMillis.state as Number
val diffSeconds = (now.millis - lastAboveZero) / 1000;
//logWarn("DDDD", diffSeconds.toString)
var Number lastVal = 0
if (SecondsNetExcessElectric.state != NULL){
lastVal = SecondsNetExcessElectric.state as Number
}
SecondsNetExcessElectric.sendCommand(lastVal + diffSeconds)
MinutesNetExcessElectric.sendCommand((lastVal + diffSeconds) / 60)
//logWarn("Count Net Electric", (lastVal + diffSeconds).toString)
}
}
catch(Exception t) {
logError("Count Excess Seconds", "Exception:" + t.getMessage())
}
finally{
PowerIsBelowZero.sendCommand(OFF)
PowerLastExcessMillis.sendCommand(now.millis)
}
}
end
That rule has fired 8000 times today spread pretty evenly over the day.
Is there a metric hiding somewhere where I can see rule execution times?
C
Fair enough, you can see better than us.
This log is a reminder - an Item change can prompt quite a bit of churning around updating groups. A group update is an iterative process, stepping through all members to calculate a new value. When you have groups of groups … there’s quite a bit of work to do.
Multiple updates of each Group Item state can be fired during this process. if you have any rules (or persistence) specifically listening for that. (So far as we know, that shouldn’t affect the separate business of Member of triggers.)
It has been noted that “funny” things can happen if you access a group while it’s ‘churning’ but I don’t recall ever seeing this deadlock type symptom. As I recall it takes the form of unexpected null members - which you’ve got covered and shouldn’t cause any hangup.
There seems no more or less likelihood of any of that being relevant depending on triggering method.
It must be something odd about running the rule in a quartz thread as opposed to “general population” thread.
May we see the current version of the rule? The last one had code commented out that would stop it working (iName undefined)
I note it exclusively uses sendCommand for what looks like updates. There may be a reason for that, but if you only want to update Item states, using postUpdate instead would save 32,000 bus events and calls of autoupdate.
I was thinking about this “minutes since” task.
Group gLastMotions
Group gMinuteCounters
DateTime xxx_LastMotion "blah" (gLastMotions)
Number xxx_MotionMinutesAgo "bleh" (gMinuteCounters) { expire="1m, command=1", autoupdate="false"}
DateTime zzz_LastMotion "blug" (gLastMotions)
Number zzz_MotionMinutesAgo "bleg" (gMinuteCounters) { expire="1m, command=1", autoupdate="false"}
expire binding provides our ticker engine, and note autoupdate disabled to separate command from state.
rule "auto reset minutes"
when
Member of gLastMotions changed
then
var cName = triggeringItem.name.replace("_LastMotion", "_MotionMinutesAgo")
postUpdate( cName, "0")
end
rule "auto count minutes"
when
Member of gMinuteCounters received command
then
triggeringItem.postUpdate( (triggeringItem.state as Number) + 1)
end
Probably needs finishing regarding system startup and so on. The timing will not be super millisecond accurate.
No group iterations (yuk) , no cron (double yuk) at least not where we can see it 
That’s a whole lot of Cron triggered rules and they all trigger on second 0 of the minute. This many Cron triggered rules is, in all the years I’ve provided support on this forum, unprecedented.
This far you’ve provided no evidence to convince me that the root cause of the other is too many of these roles trying to run at exactly the same moment in time. You seem to be getting to find the cause in anything else but that so I cannot offer any other advice.
I’m convinced the solution is to:
-
Reduce the number of Cron trusted rules, rely on events and combine rules where possible
-
Stagger the seconds so they all trigger at treat a few seconds apart instead of everything in second 0.
Nothing your other rules are doing would explain this error, unless they too are using quartz threads (i.e creating timers). Nothing the binding is doing would explain the error because the binding can’t block a rule.
I’ve not gone away, I’m on holiday at the moment 
Not able to look into this untitled I’m backing.
I see this is (potentially) happening to others.
That is a post from nearly two years ago, was occurring on OH 2.1, and according to the later posts in that thread they have not had any issues since upgrading to OH 2.4 and moving off of the SD card and on to an SSD.