openhab-core
openhab-core copied to clipboard
openhab
[automation] Make rule engine threading configurable
Originally submited by @kaikreuzer in https://github.com/openhab/openhab-core/pull/1857
Reverted in https://github.com/openhab/openhab-core/pull/1890 because of https://github.com/openhab/openhab-core/issues/1889.
Users with lower memory available (Pi2/Pi3/etc) seem to be having OutOfMemory issues because of the rules engine. See: https://community.openhab.org/t/openhab-3-runs-out-of-memory-java-heap-space-errors-cpu-100-after-a-few-hours/110924
Some users had success with the issue because of https://github.com/openhab/openhab-core/issues/2031 but others did not.
To accommodate for all variety of users, this puts the default as a threadpool but allows the user to set the pool size to "-1" to force single threading. In theory, this should allow the full spectrum of users to have the ability to tune this for their system.
Configuration in services/runtime.cfg would be "org.openhab.threadpool:automation=-1" to disable threadpool to cover the use case of higher end systems.
I would suggest also that this be noted in the release notes as this can cause issues with users who have not been having issues in a single thread per rule environment. Option 2 would be to set default to -1 and force users to configure a positive value to clamp it down to a threadpool. I'm not sure where to set that default, I would need someone to either tell me where to make the code change or push a commit to my branch.
This pull request has been mentioned on openHAB Community. There might be relevant details there:
https://community.openhab.org/t/openhab-3-runs-out-of-memory-java-heap-space-errors-cpu-100-after-a-few-hours/110924/76
I have no doubt you're right about that, but I have no idea why or how to avoid that. Totally up for suggestions here on how to not have that happen.
The bad news is that I don't know how to do it either - would need to deeply dive into the code to see how it can be best addressed.
If I remember correctly, OH2.5 used a pool for rules. While I know OH3 has a totally different approach, how was this solved in OH2.5? That may give us a path to go down.
Also to note, I've put the test jar for this onto my system and enabled logging so I should hopefully see if I get the "Failed to execute rule ‘cdf8ab1ce1' with status 'RUNNING'" messages like noted in https://github.com/openhab/openhab-core/issues/1868
EDIT: Nevermind, I fired off a test rule that has a whole bunch of triggers and 1000% caused the RUNNING error.
What if instead of using a hard setting like IDLE or RUNNING, we do this numerically? For example, rule is IDLE it is set to 0. Every time the rule fires we +1. Every time a rule ends we -1. This would give us awareness of how many parallel executions are happening at any one time across the system.
This would be a huge change, not just in the rule engine, but also in the behavior and the UI...
Sorry, I don't think I explained that properly, but now looking at it there are other reasons to not fire multiple of the same rule in parallel.
If I'm understanding the issue, when we run single threaded we effectively cause a queue effect because there isn't a thread to actually execute these in parallel whereas being in a threadpool allows for the simultaneous execution. Could we establish some sort of queue that would delay the execution of runRule() if the rule is marked as RUNNING when using threadpools? Or, is there another way to cause a "log jam" when the rule is RUNNING?
Yes, I think we would need to somehow check whether a rule is running and only assign a thread to a new task, if this is not the case. So we'd have to end up with a queue for every single rule in order to keep track of their individual executions...
I think I may have a way to do this. I'll see if I can test something tomorrow.
@kaikreuzer I have attempted to resolve this with the recent commit. Effectively, trying to track every rule in a queue was becoming complex and likely unnecessary. Instead of doing that, I've created a mechanism that pauses the thread for a preset amount of time and then re-executes itself if the rule is running already. To avoid an endless loop I've put a max iterations in. I tested this on my system and this seems to work pretty well. Under "normal conditions" I rarely see more than 4 iterations (honestly usually only 1 or 2). At system start this can run up into the dozens but it does eventually catch. Single threaded operation just fires immediately and does not attempt to do this.
This pull request has been mentioned on openHAB Community. There might be relevant details there:
https://community.openhab.org/t/persistance-rule-freezing-system/115774/15
Will this cause an issue with https://github.com/openhab/openhab-core/pull/2057 ?
This pull request has been mentioned on openHAB Community. There might be relevant details there:
https://community.openhab.org/t/openhab-3-runs-out-of-memory-java-heap-space-errors-cpu-100-after-a-few-hours/110924/105
I've posted https://community.openhab.org/t/openhab-3-runs-out-of-memory-java-heap-space-errors-cpu-100-after-a-few-hours/110924/105 to request testing on this from the community that is having the issue. It has what is commited to this PR as well as a few extra debugs to make sure https://github.com/openhab/openhab-core/pull/2057 is doing what it's supposed to (it is the only rules based PR I can see that was part of 3.0.1 which people are saying introduced this issue). I'm waiting for test results to see if this resolves the issue.
One thing to consider if we move forward with commiting this is that this is a "possibly breaking change" in the fact that we are by default enabling threadpools (which is different from the current). Options I see to address this are:
- Make a note on the release notes that people who want to continue to use single thread need to set this to -1
- Set this to -1 by default (I have no idea where in the code we would need to do this, happy to make the change if someone can point me to it).
Since it appears to be a minority of users who are encountering the problem I'd vote for 2 as being the least disruptive approach. Making -1 the default will also mean only those users who encounter the problem where they need to enable the thread pool will have to once again start worrying about running out of rules threads in the pool with long running rules like was the case in OH 1.x/2.x.
It's also worth noting that there was at least some anecdotal evidence that the thread pool does cause a performance hit over the one thread per rule, at least the way it was implemented back before it was taken back out.
Since it appears to be a minority of users who are encountering the problem I'd vote for 2 as being the least disruptive approach.
We could also argue differently: openHAB always used a threadpool for rules and it does so in ALL places where there's the risk of having no upper bound for threads being created. Not having the pool in place for 3.0 was an undesired regression since I failed getting it in place in a reliable way - I actually still have a bad feeling about having it unlimited in 3.0. My vote would hence be to rather have a pool by default - under the assumption that we get a similar behavior as we had in 2.x. For the hopefully rare cases that run into issues, we could offer the configuration option to fully deactivate the pool. Wdyt?
I've created a mechanism that pauses the thread for a preset amount of time and then re-executes itself if the rule is running already
If I am reading this logic correctly, it blocks the (triggered)-calling thread until the rule is idle and the task is handed over to the scheduler, correct? If so, I am afraid that this can easily cause problems, since for long running rules, their queue of executions can pile up, which will result in blocked threads, while the triggered method is expected to return immediately (it is e.g. called from ItemStateTriggerHandler and can thus lead to issues like https://github.com/openhab/openhab-core/issues/1887. Also, @MikeJMajor's use case will likely last 12*200ms instead of executing it as fast as possible - we should hence better find a way to properly queue the tasks and execute them without pausing inbetween.
Wrt disabling the threadpool: I'd prefer to introduce a dedicated boolean configuration option instead of introducing an implicit semantic for "-1". Firstly, because it would be an explicit semantic for that option and secondly because I would want to avoid some threadpool configurations working differently than others. Since we have many configurable threadpools and (afaik) none of those work with "-1" for disabling them, it doesn't feel good to do an exception here.
Since it appears to be a minority of users who are encountering the problem I'd vote for 2 as being the least disruptive approach.
We could also argue differently: openHAB always used a threadpool for rules and it does so in ALL places where there's the risk of having no upper bound for threads being created. Not having the pool in place for 3.0 was an undesired regression since I failed getting it in place in a reliable way - I actually still have a bad feeling about having it unlimited in 3.0. My vote would hence be to rather have a pool by default - under the assumption that we get a similar behavior as we had in 2.x. For the hopefully rare cases that run into issues, we could offer the configuration option to fully deactivate the pool. Wdyt?
I've had very good luck with the way 3.0 has been implemented thus far. My logic here would be that "people with a bunch of rules likely have a pretty big system and will likely have enough memory to support this implementation." I'm sorry, but a Pi4 isn't overly expensive compared to the cost of most of the things OH attaches to and should be more than ample to handle hundreds if not thousands of rules. If your system is truly that big, and you really have that issue, you may just need to upgrade the box that you have OH on. I don't mean to be harsh in that statement either, it's just reality if you're spending likely thousands on automation products but not on the controller then that's probably not the best thing either. I'm still of the opinion that default should be no pools with the option to enable.
I've created a mechanism that pauses the thread for a preset amount of time and then re-executes itself if the rule is running already
If I am reading this logic correctly, it blocks the (
triggered)-calling thread until the rule is idle and the task is handed over to the scheduler, correct? If so, I am afraid that this can easily cause problems, since for long running rules, their queue of executions can pile up, which will result in blocked threads, while thetriggeredmethod is expected to return immediately (it is e.g. called fromItemStateTriggerHandlerand can thus lead to issues like #1887. Also, @MikeJMajor's use case will likely last 12*200ms instead of executing it as fast as possible - we should hence better find a way to properly queue the tasks and execute them without pausing inbetween.
Correct. Honestly, I'm at my upper limit of what I remember how to do in terms of creating a queue for something like this in Java. I'm more than open to someone providing input on how to do this better. This was the first stab at doing something like this. I really didn't want to have to create a queue-per-rule to store it all, that just seemed like it would also be a memory hog and not really buy us anything in the end. That said, I have some pretty complex (several thousand) line rules and in my testing my queue never got beyond 4 (minus right at startup and then it cleared out). I would say that rules with long thread::sleep would be a problem however with something like this, but also I would point them to the post from @rkoshak about why that's really bad anyway.
Wrt disabling the threadpool: I'd prefer to introduce a dedicated boolean configuration option instead of introducing an implicit semantic for "-1". Firstly, because it would be an explicit semantic for that option and secondly because I would want to avoid some threadpool configurations working differently than others. Since we have many configurable threadpools and (afaik) none of those work with "-1" for disabling them, it doesn't feel good to do an exception here.
Agreed. The code implementation of ThreadPoolManager seemed to take any configuration sent to it and assume that we were asking for a threadpool of that size to be created. I didn't want to mangle more of that logic up by creating a boolean hence why I went with the -1 option. I'm also open to making a boolean out of this, I just didn't want to create a whole separate configuration section for one item. If there is a better place to add a boolean, I'm totally up for it just point me in the right direction and I'll make the changes.
I made the config accept both integer and boolean. If you configure the setting as "false" it uses single thread per rule. If you configure an integer, it uses a thread pool. Configuring as "true" forces it to use the default.
EDIT: Ignore previous comment, I found the issue and resolved it.
After several annoying typos, it works as expected.
2021-02-20 22:57:02.267 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value '30'
2021-02-20 22:57:02.267 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as 30
2021-02-20 22:57:03.032 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value '30'
2021-02-20 22:57:03.032 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as 30
2021-02-20 22:57:03.053 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value '30'
2021-02-20 22:57:03.053 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as 30
2021-02-20 22:57:05.536 [DEBUG] [penhab.core.common.ThreadPoolManager] - Size for thread pool 'automation' configured as 30
2021-02-20 22:57:05.536 [DEBUG] [penhab.core.common.ThreadPoolManager] - Created thread pool 'automation' with size 30
2021-02-20 22:57:05.536 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 30 true
2021-02-20 22:57:05.536 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule aeefe05726 using threadpool.
2021-02-20 22:57:07.462 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 30 true
2021-02-20 22:57:07.463 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule test2-1 using threadpool.
2021-02-20 22:57:57.445 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'true'
2021-02-20 22:57:57.448 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': true. Comparing as a boolean next.
2021-02-20 22:57:57.448 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as true
2021-02-20 22:57:58.223 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'true'
2021-02-20 22:57:58.223 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': true. Comparing as a boolean next.
2021-02-20 22:57:58.223 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as true
2021-02-20 22:57:58.234 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'true'
2021-02-20 22:57:58.234 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': true. Comparing as a boolean next.
2021-02-20 22:57:58.234 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as true
2021-02-20 22:58:00.727 [DEBUG] [penhab.core.common.ThreadPoolManager] - Size for thread pool 'automation' configured as 5
2021-02-20 22:58:00.727 [DEBUG] [penhab.core.common.ThreadPoolManager] - Created thread pool 'automation' with size 5
2021-02-20 22:58:00.723 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 5 true
2021-02-20 22:58:00.724 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule aeefe05726 using threadpool.
2021-02-20 22:58:02.653 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 5 true
2021-02-20 22:58:02.654 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule test2-1 using threadpool.
2021-02-20 22:59:09.313 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'false'
2021-02-20 22:59:09.313 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': false. Comparing as a boolean next.
2021-02-20 22:59:09.313 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as false
2021-02-20 22:59:10.057 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'false'
2021-02-20 22:59:10.058 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': false. Comparing as a boolean next.
2021-02-20 22:59:10.058 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as false
2021-02-20 22:59:10.074 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool config for pool 'automation' value 'false'
2021-02-20 22:59:10.074 [WARN ] [penhab.core.common.ThreadPoolManager] - Ignoring invalid configuration for pool 'automation': false. Comparing as a boolean next.
2021-02-20 22:59:10.074 [DEBUG] [penhab.core.common.ThreadPoolManager] - Thread pool 'automation' configured as false
2021-02-20 22:59:12.573 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 5 false
2021-02-20 22:59:12.573 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule aeefe05726 using single thread.
2021-02-20 22:59:14.461 [DEBUG] [e.automation.internal.RuleEngineImpl] - Automation threadpool configured as 5 false
2021-02-20 22:59:14.461 [DEBUG] [e.automation.internal.RuleEngineImpl] - Firing rule test2-1 using single thread.
For the hopefully rare cases that run into issues, we could offer the configuration option to fully deactivate the pool. Wdyt?
The problem is they were not rare. At least once a week there would be someone with a "my rule won't run, why?" and then after spending half an hour dragging information out of them we discover they have rules that take seconds to complete or reentrant locks. And those are just those users who bothered to ask for help. Who know how many users simply gave up and moved on.
These past couple months have been really nice to not have to deal with the running out of threads issues. It's saved me personally many many hours of support time. I've only had to address the thread pool issue twice for a couple of users still on 2.5 (notice, even with the crowd moving to OH 3 this issue has still cropped up more than once since OH 3.0 release).
If we go back to creating a thread pool, especially one with a very small pool, we're right back into the "Why have my rules stopped running" territory again.
In my experience, there are fewer people having problems with the current OH 3 behavior than there were with a limited thread pool.
ALL places where there's the risk of having no upper bound for threads being created.
But isn't this case a little different? There is kind of a natural limit here because a user has to actually create a rule to create a thread. There isn't some process that can run amok generating threads (unless something else is wrong here). There is also a bit of downward pressure on users to create fewer rules rather than more rules just based on maintenance and updates.
Do we have a measurement for how much RAM a typical rules thread consumes? Are we quibbling over a few MB or are we talking about hundreds of MB for say 100 rules (which would be on the upper end for the number of rules for the average user)?
I would say that rules with long thread::sleep would be a problem however with something like this, but also I would point them to the post from @rkoshak about why that's really bad anyway.
It's easy to point and find thread::sleep. And reentrant locks are no longer really needed (so long as we keep it where any given rule can only have one copy running at the same time) except in really rare cases so those won't be a problem going forward. But that's not the only source. executeCommandLine and all the sendHttpXRequest Actions can also take a long time to return (seconds and seconds). I imagine other bindings will have Actions that can take a long time to return as well. These normal every day core openHAB calls that users need to use can cause problems too.
We can't just say "use a timer instead of sleeps". If they are running out of threads because of a shell script is taking too long about all we can suggest is "don't run it on openHAB."
I would say that rules with long thread::sleep would be a problem however with something like this, but also I would point them to the post from @rkoshak about why that's really bad anyway.
It's easy to point and find thread::sleep. And reentrant locks are no longer really needed (so long as we keep it where any given rule can only have one copy running at the same time) except in really rare cases so those won't be a problem going forward. But that's not the only source. executeCommandLine and all the sendHttpXRequest Actions can also take a long time to return (seconds and seconds). I imagine other bindings will have Actions that can take a long time to return as well. These normal every day core openHAB calls that users need to use can cause problems too.
We can't just say "use a timer instead of sleeps". If they are running out of threads because of a shell script is taking too long about all we can suggest is "don't run it on openHAB."
That's fair. I was using the thread::sleep as an example of where people were causing rules to run for too long. You're point is completely valid.
For the hopefully rare cases that run into issues, we could offer the configuration option to fully deactivate the pool. Wdyt?
The problem is they were not rare. At least once a week there would be someone with a "my rule won't run, why?" and then after spending half an hour dragging information out of them we discover they have rules that take seconds to complete or reentrant locks. And those are just those users who bothered to ask for help. Who know how many users simply gave up and moved on.
These past couple months have been really nice to not have to deal with the running out of threads issues. It's saved me personally many many hours of support time. I've only had to address the thread pool issue twice for a couple of users still on 2.5 (notice, even with the crowd moving to OH 3 this issue has still cropped up more than once since OH 3.0 release).
If we go back to creating a thread pool, especially one with a very small pool, we're right back into the "Why have my rules stopped running" territory again.
In my experience, there are fewer people having problems with the current OH 3 behavior than there were with a limited thread pool.
I agree here as well. I do think that the number of people who need this is a very small subset of the userbase.
@kaikreuzer I've been doing some chewing on the queueing comments you made and ran a few tests to see if I could produce that error. I attempted to create a very bad rule that paused the thread for over a second and then trigger it very quickly from a bunch of different triggers. Results below. I ran it first with a 1 second delay and in single thread mode. As you can see, the rule receives all of the execution triggers very quickly and then executes sequentially over 10 seconds (as expected). I then ran it with a 2 second delay and in threadpool mode (I restarted OH in-between as well). Total execution time is (as expected) about 20 seconds. In neither case did I receive the errors noted in #1887 and the rules executed as expected.
I then attempted to make it "much worse" by executing the rule 60 times instead of 10 (by copy/pasting the 10 lines below 5 more times). Again nothing remarkable to report and it took several minutes to get through the whole batch. The only way I was able to trigger that warning was to increase the Thread::sleep above 5000 (I used 10000 in my test) and in that case it fired each time and the rule still finished at the 10 second mark (which is all expected behavior I believe for any rule running longer than 5 seconds, and has nothing to do with this). The only thing I will note interesting is that the last rule trigger doesn't fire the warning message. Single thread mode could not create the warning even at 10 seconds.
As far as the gap between, I only used 200ms as a starting point for the delay. I wouldn't have an issue making it substantially lower (maybe 10ms) and increasing the maximum itterations (perhaps we do 5 seconds / delay so 500 iterations for 10ms).
$ cat items/ruletest.items
Switch rule1
Switch rule2
Switch rule3
Switch rule4
Switch rule5
Switch rule6
Switch rule7
Switch rule8
Switch rule9
Switch rule0
Switch fireall10
$ cat rules/ruletest.rules
rule "fireall10"
when
Item fireall10 received command
then
rule1.sendCommand(ON)
rule2.sendCommand(ON)
rule3.sendCommand(ON)
rule4.sendCommand(ON)
rule5.sendCommand(ON)
rule6.sendCommand(ON)
rule7.sendCommand(ON)
rule8.sendCommand(ON)
rule9.sendCommand(ON)
rule0.sendCommand(ON)
end
rule "watch all 10"
when
Item rule1 received command or
Item rule2 received command or
Item rule3 received command or
Item rule4 received command or
Item rule5 received command or
Item rule6 received command or
Item rule7 received command or
Item rule8 received command or
Item rule9 received command or
Item rule0 received command
then
logInfo("RULETEST","RULE FIRED BY {}",triggeringItemName)
Thread::sleep(2000)
logInfo("RULETEST","RULE ENDED BY {}",triggeringItemName)
end
Single Thread:
2021-02-22 22:50:38.409 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '0' of rule 'ruletest-1' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.417 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'application/vnd.openhab.dsl.rule' with identifier: 0101f13f-0148-4d24-bb71-00703c55580b
2021-02-22 22:50:38.418 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-1'.
2021-02-22 22:50:38.536 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '0' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.537 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.537 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.537 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-1' is executed.
2021-02-22 22:50:38.538 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.538 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.539 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.539 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.539 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.540 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.540 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:50:38.543 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'application/vnd.openhab.dsl.rule' with identifier: 1510e805-40da-4793-aec9-aa334b7b507b
2021-02-22 22:50:38.544 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:39.548 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:39.548 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:40.550 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:40.550 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:41.552 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:41.552 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:42.554 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:42.554 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:43.556 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:43.557 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:44.559 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:44.559 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:45.561 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:45.561 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:46.563 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:46.563 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:47.565 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:50:47.566 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:50:48.567 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
Threadpool:
2021-02-22 22:53:05.011 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '0' of rule 'ruletest-1' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:05.012 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'application/vnd.openhab.dsl.rule' with identifier: 6c2abed4-4386-469b-a379-acbb95052fce
2021-02-22 22:53:05.012 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-1'.
2021-02-22 22:53:05.144 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '0' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:05.145 [DEBUG] [ipt.internal.ScriptEngineManagerImpl] - Added ScriptEngine for language 'application/vnd.openhab.dsl.rule' with identifier: 1fc3a627-147a-4d57-afbe-7717d140c16b
2021-02-22 22:53:05.145 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:05.145 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:05.147 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-1' is executed.
2021-02-22 22:53:05.346 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:05.546 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:05.747 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:05.947 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:06.147 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:06.348 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:06.548 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:06.749 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:06.949 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:07.149 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. Rule execution paused (11/100)
2021-02-22 22:53:07.150 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:07.350 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '1' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:07.351 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:07.351 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:07.552 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:07.752 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:07.952 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:08.153 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:08.353 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:08.554 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:08.754 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:08.954 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:09.155 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:09.353 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:09.355 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '2' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:09.355 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:09.356 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:09.556 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:09.756 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:09.957 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:10.157 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:10.358 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:10.558 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:10.759 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:10.959 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:11.160 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:11.357 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:11.360 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '3' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:11.360 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:11.361 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:11.561 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:11.761 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:11.962 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:12.162 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:12.363 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:12.563 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:12.763 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:12.964 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:13.164 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:13.362 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:13.364 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '4' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:13.365 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:13.365 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:13.566 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:13.766 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:13.966 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:14.167 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:14.367 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:14.567 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:14.768 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:14.968 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:15.168 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:15.366 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:15.369 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '5' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:15.369 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:15.369 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:15.570 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:15.770 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:15.971 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:16.171 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:16.371 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:16.572 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:16.772 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:16.973 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:17.173 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:17.371 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:17.373 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '6' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:17.373 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:17.374 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:17.575 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:17.775 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:17.976 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:18.176 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:18.376 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:18.577 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:18.777 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:18.978 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:19.178 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:19.375 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:19.378 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '7' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:19.378 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:19.381 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:19.581 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:19.782 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:19.982 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:20.182 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:20.383 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:20.583 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:20.784 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:20.984 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:21.184 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:21.380 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:21.385 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '8' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:21.385 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:21.385 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (1/100)
2021-02-22 22:53:21.585 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (2/100)
2021-02-22 22:53:21.786 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (3/100)
2021-02-22 22:53:21.986 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (4/100)
2021-02-22 22:53:22.187 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (5/100)
2021-02-22 22:53:22.387 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (6/100)
2021-02-22 22:53:22.587 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (7/100)
2021-02-22 22:53:22.788 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (8/100)
2021-02-22 22:53:22.988 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (9/100)
2021-02-22 22:53:23.189 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. Rule execution paused (10/100)
2021-02-22 22:53:23.387 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
2021-02-22 22:53:23.389 [DEBUG] [e.automation.internal.RuleEngineImpl] - The trigger '9' of rule 'ruletest-2' is triggered. - Rule Status: 'IDLE' - Rule Executed.
2021-02-22 22:53:23.390 [DEBUG] [time.internal.engine.DSLScriptEngine] - Script uses context 'ruletest-2'.
2021-02-22 22:53:25.392 [DEBUG] [e.automation.internal.RuleEngineImpl] - The rule 'ruletest-2' is executed.
Sleep set to 10000 and 10 triggers
2021-02-22 23:07:18.358 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule1
2021-02-22 23:07:23.358 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@60fd4558' takes more than 5000ms.
2021-02-22 23:07:28.359 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule1
2021-02-22 23:07:28.376 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule2
2021-02-22 23:07:33.377 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@406c316c' takes more than 5000ms.
2021-02-22 23:07:38.377 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule2
2021-02-22 23:07:38.396 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule3
2021-02-22 23:07:43.397 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@3619a823' takes more than 5000ms.
2021-02-22 23:07:48.397 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule3
2021-02-22 23:07:48.413 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule4
2021-02-22 23:07:53.412 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@155b0187' takes more than 5000ms.
2021-02-22 23:07:58.413 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule4
2021-02-22 23:07:58.433 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule5
2021-02-22 23:08:03.433 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@1f8641f1' takes more than 5000ms.
2021-02-22 23:08:08.433 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule5
2021-02-22 23:08:08.449 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule6
2021-02-22 23:08:13.450 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@3e40e43c' takes more than 5000ms.
2021-02-22 23:08:18.451 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule6
2021-02-22 23:08:18.463 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule7
2021-02-22 23:08:23.463 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@45e31b67' takes more than 5000ms.
2021-02-22 23:08:28.464 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule7
2021-02-22 23:08:28.481 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule8
2021-02-22 23:08:33.481 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@8f97d65' takes more than 5000ms.
2021-02-22 23:08:38.481 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule8
2021-02-22 23:08:38.498 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule9
2021-02-22 23:08:43.498 [WARN ] [ab.core.internal.events.EventHandler] - Dispatching event to subscriber 'org.openhab.core.automation.internal.module.handler.ItemCommandTriggerHandler@25dd3c42' takes more than 5000ms.
2021-02-22 23:08:48.498 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule9
2021-02-22 23:08:48.521 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE FIRED BY rule0
2021-02-22 23:08:58.523 [INFO ] [g.openhab.core.model.script.RULETEST] - RULE ENDED BY rule0
Also to answer my own question, we would need to add a line to distributions/openhab/src/main/resources/runtime/services.cfg in openhab-distro that sets threadpool:automation to a default that isn't 5 if we want to commit this so that it is set on start/install properly. I can submit a PR to openhab-distro to make this change if/when we get to that point and decide what to do with this.
@rkoshak One last spam message for you to ponder from your experience. You make a note that other things also take an equally long amount of time outside of the rules. Are these things that need to be pulled out into their own threadpool so that they don't trample on "other things that run fast"? Are these things that also need to have a single thread option (e.g. the executeCommandLine and sendHttpXRequest as you mentioned)? I'm thinking about this from a "wholistic platform growth/evolution/optimization" standpoint. I'm not opposed to taking on a separate side task of creating the PRs to either pull those off or make it optional through config like we are doing here. Just looking for general thoughts here, not to cloud this PR.
Are these things that need to be pulled out into their own threadpool so that they don't trample on "other things that run fast"?
I don't think there is a way to do that effectively. For example, you can provide a Duration to the executeCommandLine Action to say "wait up to this amount of time for a result". If you omit that it will immediately return. But of course that also means you don't care about what the script returned. When you provide the Duration, it probably means you want to process the results. And if that's the case you probable want to do it inside that same rule. Otherwise you'd create a Thread.
I suppose one could modify executeCommandLine to accept a lambda to process the results and that lambda could run from a separate pool. But then you'd have a nesting dolls situation where you may want to call executeCommandLine again based on the results from the first call. It feels kind of messy.
I imagine with the sendHttpXRequest Actions one would always want to process the results.
So I think, from a global perspective, in cases where you don't care about the result these long running Actions should provide a version that immediately returns. executeCommandLine already does this, I don't know about the rest.
But, if we do need to process the results, if feels kind of awkward to have to pass lambdas to the Actions to process the results.
To give one example, I'm playing around with the Honeywell Home API in some rules. When the AuthToken expires I think I'll have at least two, maybe three calls to a sendHttpXRequest, each one depending on the results from the previous call. That's a lot of nesting.
But if it helps the rules threading over all maybe that's what's required. But I like the simplicity, especially for new users, of not needing to care about such things. They can code things in a straight forward and wasteful manner using sleeps and the like without running into exhausting the threadpool. As they gain experience, they usually go back and fix that by converting them to timers, and I've created some libraries in Python and JavaScript for rules so managing timers in certain ways becomes really easy.
Are these things that need to be pulled out into their own threadpool so that they don't trample on "other things that run fast"?
I don't think there is a way to do that effectively. For example, you can provide a Duration to the executeCommandLine Action to say "wait up to this amount of time for a result". If you omit that it will immediately return. But of course that also means you don't care about what the script returned. When you provide the Duration, it probably means you want to process the results. And if that's the case you probable want to do it inside that same rule. Otherwise you'd create a Thread.
I suppose one could modify executeCommandLine to accept a lambda to process the results and that lambda could run from a separate pool. But then you'd have a nesting dolls situation where you may want to call executeCommandLine again based on the results from the first call. It feels kind of messy.
I imagine with the sendHttpXRequest Actions one would always want to process the results.
So I think, from a global perspective, in cases where you don't care about the result these long running Actions should provide a version that immediately returns. executeCommandLine already does this, I don't know about the rest.
But, if we do need to process the results, if feels kind of awkward to have to pass lambdas to the Actions to process the results.
To give one example, I'm playing around with the Honeywell Home API in some rules. When the AuthToken expires I think I'll have at least two, maybe three calls to a sendHttpXRequest, each one depending on the results from the previous call. That's a lot of nesting.
But if it helps the rules threading over all maybe that's what's required. But I like the simplicity, especially for new users, of not needing to care about such things. They can code things in a straight forward and wasteful manner using sleeps and the like without running into exhausting the threadpool. As they gain experience, they usually go back and fix that by converting them to timers, and I've created some libraries in Python and JavaScript for rules so managing timers in certain ways becomes really easy.
That all works for me. If it doesn't make sense to do it anywhere else, then no point in doing it.
@morph166955 Why did you close this? It was the next thing I wanted to look into after finishing the jUPnP stuff...
FYI, the GraalJS engine which is used in the new JS add-on only permits a single (concurrent) thread per engine (script file). This caused a similar issue to the concurrently one being discussed, in that concurrent execution of a single rule would throw exceptions.
I worked around this in the add-on by synchronising access to each engine, but it would be great not to require this.
@jpg0 This PR is not about allowing concurrent execution, it is merely about reusing threads from a pool. So I guess your GraalJS implementation is just in line with this and you shouldn't expect any changes to that behavior (I'm pretty sure we would also run into trouble with Xtext rules being concurrently executed).
I am not yet happy with the "iterator + blocking" approach of the current PR, though. But as I don't hear anybody screaming for a rule thread pool right now, this has low prio for me and I'm not sure when I can find the time to come up with a better suggestion/implementation.