since a while, I am struggling with delayed execution of rules that are triggered by “Time cron”. Doing some research today, I figured out that the scheduler seems to be delayed. I lose around 1 second for every 30s (which may sum up to tens of minutes).
I have the following three rules file _test_v33.rules:
rule "Test1"
when
Time cron "0/30 * * ? * * *"
then
logInfo("TEST", "This is triggered every 30s")
end
rule "Test2"
when
Time cron "0 0/2 * ? * * *"
then
logInfo("TEST", "This is triggered every 2mins")
end
rule "Test3"
when
Time cron "0 0/5 * ? * * *"
then
logInfo("TEST", "This is triggered every 5mins")
end
This produces the following logs:
2021-06-03 22:30:31.109 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:31:01.575 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:31:31.288 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:32:01.602 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:32:04.697 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
2021-06-03 22:32:31.035 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:33:01.752 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:33:31.517 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:34:01.631 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:34:05.038 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
2021-06-03 22:34:30.295 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:35:01.323 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:35:11.203 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 5mins
2021-06-03 22:35:31.041 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:36:01.172 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:36:02.946 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
2021-06-03 22:36:31.384 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:37:01.970 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:37:31.905 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:38:01.590 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:38:05.956 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
2021-06-03 22:38:31.401 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:39:01.116 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:39:30.300 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:40:01.811 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:40:03.739 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
2021-06-03 22:40:11.909 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 5mins
2021-06-03 22:40:31.936 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:41:01.673 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:41:31.576 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:42:01.921 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 30s
2021-06-03 22:42:06.224 [INFO ] [org.openhab.core.model.script.TEST ] - This is triggered every 2mins
I am using openhab 3.0.2 and since yesterday 3.1.0M5. No difference here. The system is a Raspberry Pi4 with 4G RAM (Raspbian GNU/Linux 10 (buster)), no virtualization. I tried java zulu11.43.88-ca-jdk11.0.9-linux_aarch32hf and java-11-openjdk-armh, also no difference.
I am happy for any idea… Thanks, Lui!
Happy for any idea to debug.
First of all it’s important to understand that openHAB is not a real time system. If a cron job runs 2 seconds after it’s supposed to, it is not an error. If you require the rules to run with that sort of precision, openHAB is not the platform to build what ever it is you are building. So part of what is going on here I think is that openHAB cannot meet your expectations in terms of precision.
As far as I can see for the every 30 second rule there is around a 1.5 second latency from when it was scheduled to when the log statement appear. That doesn’t necessarily mean that the rule started running that late, that that is a reasonable assumption. And, as I said, that’s not considered an error as this isn’t a real time system.
For the 2 minute rule I see the latency being between 2 and 6 seconds with five seconds being most common. That could point to the latency being higher for longer scheduled polling periods. That observation appears to hold for the five minute rule which is seeing around 12 seconds of latency.
But in all of these cases, the rules are actually running within a second of the polling period. The 30 second rule is running every 30 seconds +/-1 second. The two minute rule is running every two minutes +/-4 seconds. The five minute rule is running every five minutes +/-1 second. That’s pretty good as it means the latency isn’t growing over time. It’s just that first run introduces some latency which gets propagated.
Is there any latency in event triggered rules? That indeed would be a really big problem. You don’t want to have to wait a second after a switch is flipped before a light turns on.
That feels a little similar to the well-known OH1/2 phenomenon of rules taking a few seconds to get rolling from a first-time trigger after load.
Rule engine and scheduler have changed of course, but there’ll be fundamentals in common.
Kind of implies the scheduler doesn’t set the “next” target until the current one is rolling though, which is a surprise.
Maybe it’s worth remembering that the logger is not using the same clock as the rules engine, as evidenced by users seeing timezone oddities, quite apart from any logging latency. Try logging out the rule’s version of ‘now’ and compare to logger timestamp.
thanks for the fast reply! The example shown was only a proof of concept to illustrate my challenge.
My real scenario is the following:
I have a rule that closes raffstores at 7:30pm in the childrens’ rooms. When I install the rule at 7:00pm, the execution happens at ~7:31pm. This is totally fine; as you said, we don’t have a real time system here. And it is obviously not needed for this task.
However, on the following two days, the scheduled rule was executed at ~8:18pm, which is 48 minutes later than scheduled by the cron expression. This cannot be explained with a fixed offset created by the first execution. It seems that latency is indeed growing over time: the scheduler somehow “looses time”. When I redeployed the rule today at around 6:00pm, the execution happened at 7:33pm. This led me to the observation that the scheduler looses around a second every thirty seconds.
I it clear to me that the clock may loose some time due to the operating system scheduler. But 3% is much too high. I never observed such delays in openhab 2.x, only when rules were complied for the first time. However, the second execution was then always very close to the scheduled point in time.
I also know that the logger is not using the same time. However, I can see when the raffstores actually move, meaning that this is not a logging problem.
So, the problem must be something different: I for sure can bypass the problem somehow (e.g. by a time-based trigger created out of my Smart Home system I integrate), but I would like to understand what’s behind…
In case you have further ideas, happy to discuss. Btw, can I somehow get logs from the quarry scheduler?
I believe you but the logs above do not show that.
I don’t really have any good ideas. It would be interesting to see if a Timer scheduled that far out into the future has a similar drifting problem or if it’s just the cron triggers.
I assume you’ve already checked the CPU and overall system load of the machine to ensure that OH isn’t being starved of resources. Is swap enabled and is it being used?
I doubt this is a common issue or else there would be hundreds of irate users on the forum complaining their cron rules are half an hour+ delayed over time. That is unreasonable. So we need to find out what it unique about your setup/machine to begin to understand how to fix it.
Out of curiosity, do you see similar delays on an OS cron triggered script? That would at least tell us it’s definitely an OH issue and not a system wide problem.
I don’t know if the scheduler has any logging. I don’t think it’s Quartz any more though. I vaguely remember it was swapped out for a different library before OH 3.0 was released.
thanks for the effort and your thoughts. It is pretty clear that this is not a mass phenomena, otherwise there would be indeed dozens of discussions. I will keep investigating - and update that discussion.
For now I have created a test rule that creates a log with timestamp 1) every 12h, 2) after a timer of 12h, and 3) after a sleep of 12h. Let’s see what happens…
rule "Test3"
when
Time cron "0 0 0/12 ? * * *"
then
val String createdAt = now.toLocalDateTime().toString()
logInfo("TEST", createdAt + " This is triggered every 12h. Output directly created at (" + now.toLocalDateTime().toString() + ").")
createTimer(now.plusHours(12), [ |
logInfo("TEST", createdAt + "This is triggered every 12h. Output was created 12h ago by timer (" + now.toLocalDateTime().toString() + ").")
])
Thread::sleep(1000 * 60 * 60 * 12)
logInfo("TEST", createdAt + " This is triggered every 12h. Output was created 12h ago by sleep (" + now.toLocalDateTime().toString() + ").")
end
You should make this less than the cron time because while the rule is sleeping, it will prevent that rule from running again. In other words, that sleep could cause the next run of the rule to be delayed and mess up the cron trigger timing. Do something like 11h55 minutes for the sleep. Even better, put the sleep test in another rule to avoid the sleep from interfering with the other two tests.
thanks for the note, I changed that. I have three rules now.
The first results look like all schedules are delayed. Timer and sleep for sure. The delayed next rule execution could be a side effect from what you described but that was the initial effect I observed. Here are the logs:
2021-06-05 00:02:01.273 [INFO ] [org.openhab.core.model.script.TEST ] - 2021-06-05T00:02:01.253287 This is triggered every 12h. Output directly created at (2021-06-05T00:02:01.267916).
2021-06-05 12:55:14.237 [INFO ] [org.openhab.core.model.script.TEST ] - 2021-06-05T00:02:01.253287This is triggered every 12h. Output was created 12h ago by timer (2021-06-05T12:55:14.229672).
2021-06-05 12:55:14.266 [INFO ] [org.openhab.core.model.script.TEST ] - 2021-06-05T00:02:01.253287 This is triggered every 12h. Output was created 12h ago by sleep (2021-06-05T12:55:14.263010).
2021-06-05 12:55:14.284 [INFO ] [org.openhab.core.model.script.TEST ] - 2021-06-05T12:55:14.277270 This is triggered every 12h. Output directly created at (2021-06-05T12:55:14.281730).
This is the new test file I use:
/******************************************************************************************************************************************
* TEST ONLY
*/
rule "Test1"
when
Time cron "0 0 0/12 ? * * *"
then
val String createdAt = now.toLocalDateTime().toString()
logInfo("TEST1", createdAt + " This is triggered every 12h. Output directly created at (" + now.toLocalDateTime().toString() + ").")
end
/******************************************************************************************************************************************
* TEST ONLY
*/
rule "Test2"
when
Time cron "0 0 0/12 ? * * *"
then
val String createdAt = now.toLocalDateTime().toString()
createTimer(now.plusHours(12), [ |
logInfo("TEST2", createdAt + "This is triggered every 12h. Output was created 12h ago by timer (" + now.toLocalDateTime().toString() + ").")
])
end
/******************************************************************************************************************************************
* TEST ONLY
*/
rule "Test3"
when
Time cron "0 0 0/12 ? * * *"
then
val String createdAt = now.toLocalDateTime().toString()
Thread::sleep(1000 * 60 * 60 * 12 - (5*60*1000))
logInfo("TEST3", createdAt + " This is triggered every 12h. Output was created 12h -5mins ago by sleep (" + now.toLocalDateTime().toString() + ").")
end
It seems that clocks in real and the openhab environment get out of sync.
I did a lot with java but never observed that. In case the sleep will be delayed after that test, too, I will write an independent java file that sleeps for 12h and see what happens. Either I have the same problem (then it will be linked to java and not openhab) or not (then it must be something in my openhab setup).
Comment; the logger stamps log entries according to “java time” (and locale) without reference to what openHAB thinks at all.
If you provoke real-world events, do you get the log timestamp you expect? To gain confidence or not in “java” clock.
Just displaying a live datetime would allow to spot this level of drift.
openHAB and java should share a clock of course, albeit OH might have different time zone. Your logging does I think confirm that they agree?
sorry for the delay, I did not any time in the last days. To answer your question: yes, realtime events show exactly the time expected. There is no problem.
In the meantime, I let the test rules run for a while. The result is a constant offset of around 50mins every 12h in case of the cron-based rule (test1) and the timer (rule2). In case of a sleep, the delay sums up (which makes sense, as you said the sleep will block the next execution.
Here are the logs:
2021-06-07 04:11:12.124 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model '_test_v33.rules'
2021-06-07 12:33:55.135 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-07T12:33:55.130275 This is triggered every 12h. Output directly created at (2021-06-07T12:33:55.134921).
2021-06-08 00:50:41.881 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-08T00:50:41.862912 This is triggered every 12h. Output directly created at (2021-06-08T00:50:41.879210).
2021-06-08 01:21:44.123 [INFO ] [org.openhab.core.model.script.TEST3 ] - 2021-06-07T12:33:55.131886 This is triggered every 12h. Output was created 12h -5mins ago by sleep (2021-06-08T01:21:44.119127).
2021-06-08 01:27:09.933 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-07T12:33:55.131901This is triggered every 12h. Output was created 12h ago by timer (2021-06-08T01:27:09.932709).
2021-06-08 12:51:13.326 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-08T12:51:13.319895 This is triggered every 12h. Output directly created at (2021-06-08T12:51:13.324269).
2021-06-08 13:45:46.417 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-08T00:50:41.878486This is triggered every 12h. Output was created 12h ago by timer (2021-06-08T13:45:46.413538).
2021-06-08 14:11:31.719 [INFO ] [org.openhab.core.model.script.TEST3 ] - 2021-06-08T01:21:44.134761 This is triggered every 12h. Output was created 12h -5mins ago by sleep (2021-06-08T14:11:31.716040).
2021-06-09 00:50:49.176 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-09T00:50:49.172903 This is triggered every 12h. Output directly created at (2021-06-09T00:50:49.175299).
2021-06-09 01:45:50.939 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-08T12:51:13.320780This is triggered every 12h. Output was created 12h ago by timer (2021-06-09T01:45:50.936622).
2021-06-09 03:00:45.355 [INFO ] [org.openhab.core.model.script.TEST3 ] - 2021-06-08T14:11:31.727688 This is triggered every 12h. Output was created 12h -5mins ago by sleep (2021-06-09T03:00:45.352675).
2021-06-09 12:51:50.775 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-09T12:51:50.763997 This is triggered every 12h. Output directly created at (2021-06-09T12:51:50.771649).
2021-06-09 13:46:33.560 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-09T00:50:49.172833This is triggered every 12h. Output was created 12h ago by timer (2021-06-09T13:46:33.559511).
2021-06-09 15:51:34.847 [INFO ] [org.openhab.core.model.script.TEST3 ] - 2021-06-09T03:00:45.367316 This is triggered every 12h. Output was created 12h -5mins ago by sleep (2021-06-09T15:51:34.846909).
2021-06-10 00:52:28.921 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-10T00:52:28.909731 This is triggered every 12h. Output directly created at (2021-06-10T00:52:28.918762).
2021-06-10 01:48:33.919 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-09T12:51:50.767935This is triggered every 12h. Output was created 12h ago by timer (2021-06-10T01:48:33.916571).
2021-06-10 04:43:01.009 [INFO ] [org.openhab.core.model.script.TEST3 ] - 2021-06-09T15:51:34.850310 This is triggered every 12h. Output was created 12h -5mins ago by sleep (2021-06-10T04:43:01.006730).
2021-06-10 12:54:40.906 [INFO ] [org.openhab.core.model.script.TEST1 ] - 2021-06-10T12:54:40.895853 This is triggered every 12h. Output directly created at (2021-06-10T12:54:40.901546).
2021-06-10 13:51:21.483 [INFO ] [org.openhab.core.model.script.TEST2 ] - 2021-06-10T00:52:28.917020This is triggered every 12h. Output was created 12h ago by timer (2021-06-10T13:51:21.482107).
Hmm, I am running out of ideas… Could it be that other rules cause side effects when they block etc…?
That shouldn’t be the case in OH 3. Each rule has it’s own thread so anything short of your CPU, memory, or file IO causing a general slowdown on the machine for everything, which doesn’t seem to be the case here, other rules shouldn’t be able to block scheduled rules. And if that were the case, I wouldn’t expect the delay to be consistent.
At this point the best I have to offer is to file an issue on openhab-core and hopefully someone familiar with the code might have more ideas.
Let’s concentrate on the timer-creating TEST2 rule results
So the first timestamp represents the “now” apparent to the rule when triggered by cron
2021-06-07T12:33:55.131901
period 12h 17m
2021-06-08T00:50:41.878486
period 12h 1m
2021-06-08T12:51:13.320780
period 11h 59m
2021-06-09T00:50:49.172833
period 12h 1m
2021-06-09T12:51:50.767935
period 12h 1m
2021-06-10T00:52:28.917020
So after the first disaster, this looks like acceptable if poor performance.
However, I’m not convinced this is the right way to look at it.
What we asked for was second zero, minute zero, when hour = 00 or 12.
i.e. based on clock reading, not elapsed time.
In other words we’re consistently around 50 minutes late.
This is rubbish.
Note that we’re not really requesting a ‘duration’, with createTimer we set a future date/time.
There was previous weirdness with double-triggering of cron (it fired a few seconds early, so recheduled “next” just a few seconds ahead). I think the root of that was Pi with no RTC and poor Java substitute timekeeping.
The mitigations implemented for that look like they ought to take care of this new problem too, and should be in snapshots or milestones since March. Really sure you’re running 3.1.0M5?
thanks for checking the delays. I share you view: we ask for clock reading, so we are always late - not only one time. I am completely sure that I am using 3.1.0M5, I changed the repo accordingly and doubled checked in the UI >> “About & Help” (Über & Hilfe in German).
Where - according to my understating - do not completely agree is that the fix for earlier triggers #1976 should help. As far as I read what @hilbrand wrote, I would expect:
If the scheduler triggers > 2 sec before expected end time it will reschedule.
That will not help, as my triggers are always late.
The scheduler keeps track of the timestamp the job should run. For recurring schedulers, like cron, when the next job is run it offsets of the calculated time, and not the actual time. This guaranties that the next scheduled time is actual the next scheduled time and not the same end time in case the scheduler would trigger to early.
The fact that cron sets an offset to the calculated time helps to adjust a “one-time” difference in case the last event fires too early / late. However, when the clock runs slow, we should observe the same offset again and again. This is what I observe.
As rlkoshak said, I am quite sure that it must be something in my setup. Otherwise the forum would be full of reports describing that issue.
But I don’t know how to figure out: system CPU utilization is low (less than 10% as long as I don’t deploy large rules), I tried to assign more memory (EXTRA_JAVA_OPTS=“-Xms1024m -Xmx2560m”, real mom usage is around 1.4G/4G, no swap happens).
But you keep showing us your clock does not run slow. If your clock ran slow, the event would fire at an logged 12:00, while it was 12:50 in the real world.
It is curious. You’d expect a calculation error to be more consistent. It’s as though the scheduler runs its own clock (and something else steals cycles from that).
I am confused. I think (/hope )we mean the same but from a different perspective.
When it is 12hs until the rule should be executed and it takes 12hs and 50mins, an average second in my openhab environment is longer than in real-time. The clock in the environment runs slower - I agree, something seems to steal it cycles.
I don’t believe a calculation error. Could be of course (as I have no evidence for one or the other) but the growing offset looks for me rather like the loss of cycles.
Key question is now how to debug. Here, I struggle. I tried downgrades down to 3.0.0-1 today but I observed the same behavior.
So when you trigger some external event, it gets logged as though it happened at an earlier time than reality? And as real time progresses, the lag would get greater and greater. That would be a slow clock.
I applied a little plain java test program today to check decency of my problem on obenhab code:
import java.util.concurrent.TimeUnit;
public class Timetest {
public static void main(String args[]) {
long millis=System.currentTimeMillis();
java.util.Date date = new java.util.Date(millis);
System.out.println("Current Time is: " + date);
for (int i = 0; i < 10; i++) {
try {
TimeUnit.SECONDS.sleep(60*60*12);
millis = System.currentTimeMillis();
date = new java.util.Date(millis);
System.out.println("Run " + i + ": Current Time is :" + date);
} catch (Exception e) {
System.out.println("Error.");
}
}
}
}
The result is the following output:
Current Time is: Tue Jun 15 23:07:05 CEST 2021
Run 0: Current Time is :Wed Jun 16 11:58:38 CEST 2021
That means my problem is indeed completely independent of openhab but somewhere in between Debian or Java. I will continue to search for the root cause.
The puzzler is why, if say the clock ticks slow so that scheduled events are “late” … why would the system clock not read slow as well.
A quick internet dive threw up some stuff beyond my pay grade, but suggesting that Java scheduler does some jiggery-pokery if the system clock is changed. This jiggery-pokery is flawed apparently, and errors can accrue.
Have you got NTP configured somewhere here, and if so how frequently is it tweaking system clock? It might work better to tweak less often.
I think you post gave me the relevant hint! In order to check whether it works better when I “tweak less often” via NTP, I deactivated NTP entirely. The result of that is that after an hour, my system clock runs 4min late - a drift similar to what I observed in java.
Now it becomes logical: whenever a time is requested, openhab takes the system time from java which takes it from the NPN synced time of the system. Thus, timestamps are precise.
However, when the system sets a timer, waits, etc, the system clock is drifting, which causes the delay also in openhab/java.
This is leading to the question: why is the time of my PI running that imprecise? The normal drift of a pi seems to be around a few seconds per day - not hours.
That’s pants, about as accurate as drumming your fingers on the table Like, 67,000ppm instead of expected 200ppm or so
The java jiggery-pokery I touched on is supposed to tweak scheduled tasks to keep in step with clock adjustments, but I would imagine it is deliberately limited to less drastic tweaks than would be needed to keep pace with that.
Think you might be closing in on a hardware problem, of all things.
)we mean the same but from a different perspective.
Like, 67,000ppm instead of expected 200ppm or so