(OH 1.x and OH 2.x Rules DSL only] Why have my Rules stopped running? Why Thread::sleep is a bad idea

Ok,

Well using this I have implemented a rule that track Blocked and waiting threads. I’ll see if it gives any useful information.

If so, I’ll share…

Bear in mind what Rich said about multiple lambda calls trampling each other’s variables. I experienced this with OH1, but essentially same rule engine I believe. This of itself should not cause thread usage of course, But unexpected values could break things though.

Countering this with re-entrant locks brings its own problems. Even with try/catch/finally you can definitely error out without finally releasing a lock. I got my system working reliably by building in lots of sense checking, especially for null values.

Just to share a lesson learned here, when upgrading from 2.3.0 to the 2.4.0M releases the settings in /usr/share/openhab2/runtime/etc/quartz.properties are restored back to default. I was getting confused as to why the upgrade reintroduced all of my thread problems until I realized that this was done.

On another note with 2.4.0, I now get this when I start OH:
2018-10-06 10:27:37.530 [WARN ] [e.jetty.util.thread.ThreadPoolBudget] - Low configured threads: (max=8 - required=1)=7 < warnAt=8 for QueuedThreadPool[ServletModel-29]@21e19873{STARTING,8<=0<=8,i=0,q=0}[ReservedThreadExecutor@347e0f6b{s=0/1,p=0}]

Anyone know why this is happening? I’ve upped my threadpool counts much higher than this.

That is true. Technically speaking we are not expected to be making changes to any files in /usr/share/openhab2 so the installer will simply replace it instead of asking if you want to keep it or use the new version.

I know there is a bug in the release right now related to the RuleEngine threads. This will change at some point to ruleEngine to match the pattern set by the names of the other thread pools and it seems to be case sensitive. But That error does not match.

Magical. This one line is 100% what makes my system work properly or completely collapse.

unverified: have you tried to set the same parameters found in /usr/share/openhab2/runtime/etc/quartz.properties inside /etc/openhab2/services/runtime.cfg ?
I don’t know if this would work and/or if they will take precedence over quartz.properties

Edit: found something interesting: [KARAF-5558] Be able to configure the Quartz Scheduler - ASF JIRA

(untested) so according to this, you can use runtime.cfg and set org.quartz.threadPool.threadCount=x etc to modify the quartz. Not exactly sure on the syntax… you need to play with this :slight_smile:

1 Like

Tried to set it in runtime.cfg instead of quartz.properties when I upgraded to 2.4.0 release, no luck.

there is a specific format for setting parameters in runtime.cfg

how did you list the config parameters there? (I tried guessing but I ran out of blue pills :wink:)

It may not work… I mentioned in the previous post that this was untested

Hello,

I have the following problem. Due to speed issues I have to send several command to a KNX actor with a pause of 1000ms between every command. Until today, I am using Thread::Sleep(1000).
Today I tried to change my rule to the following:

rule "Betriebsarten Heizung"
when
Item Heizung_Betriebsart changed
then
    
if(Heizung_Betriebsart.state==1) {
        //Heizung in Komfort (=1) schalten und Standby (=2)
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalA_Betriebsart, 1)  //Wohnzimmer in Komfort
        logInfo("rules","1")     
    ])
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalB_Betriebsart, 1)  //Küche in Komfort
        logInfo("rules","2")
    ])
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalC_Betriebsart, 1)  //Flur EG in Komfort
        logInfo("rules","3")
    ])  
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalH_Betriebsart, 1)  //Gäste WC in Komfort
        logInfo("rules","4")
    ])    
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalD_Betriebsart, 1)  //Kinderzimmer in Komfort
        logInfo("rules","5")
    ])    
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalE_Betriebsart, 2)  //Schlafzimmer in Standby
        logInfo("rules","6")
    ])   
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalF_Betriebsart, 2)  //Badezimmer in Standby
        logInfo("rules","7")
    ])   
    createTimer(now.plusSeconds(1), [ |
        sendCommand(Heizung_KanalG_Betriebsart, 2)  //Speicher in Standby
        logInfo("rules","8")
    ])            
        sendTelegram("johannes","Heizung auf Anwesenheitsmodus geschaltet")
        logInfo("rules","Heizung auf Anwesenheitsmodus geschaltet")
}
//.... and so on for the different modes of operation

I have a logInfo in every Timer to check it in the logs, but it seems there is no time delay between the commands. What is my failure?

Thank you for your help.

Only the code inside createTimers angle brackets is executed after the delay. The timer doesn’t block and wait for itself to finish.

With your code the timers are created almost instantly. And when they have the same delay the code execution inside angle brackets happens at the same time.

Try putting 1 second delay in the first timer, 2 seconds in second timer, …

1 Like

Ah ok, I understand, I thought that the timers start step by step, after each other. Last question: Is a timer in my case better than threadsleeps?

Thank you!

If sleep is longer than ~200ms then I’d say timer is better.

1 Like

Thank you! I will try it.

instead of build a bunch of timers, a more apropriate way would be a state machine:

var Integer iCounter 
var Timer tHeizung 

rule "Betriebsarten Heizung"
when
    Item Heizung_Betriebsart changed
then
    tHeizung?.cancel
    iCounter = 0
    logInfo("heizung","Heizung Betriebsart neu: {} ",Heizung_Betriebsart.state)
    if(Heizung_Betriebsart.state as Number == 1)
        tHeizung = createTimer(now,[|
            iCounter += 1
            logInfo("heizung","Heizung Schritt {} ",iCounter)
            switch iCounter {
                case 1: Heizung_KanalA_Betriebsart.sendCommand(1) //Wohnzimmer
                case 2: Heizung_KanalB_Betriebsart.sendCommand(1) //Küche
                case 3: Heizung_KanalC_Betriebsart.sendCommand(1) //Flur EG
                case 4: Heizung_KanalH_Betriebsart.sendCommand(1) //Gäste WC
                case 5: Heizung_KanalD_Betriebsart.sendCommand(1) //Kinderzimmer
                case 6: Heizung_KanalE_Betriebsart.sendCommand(2) //Schlafzimmer
                case 7: Heizung_KanalF_Betriebsart.sendCommand(2) //Badezimmer
                case 8: Heizung_KanalG_Betriebsart.sendCommand(2) //Speicher
                default: {
                    sendTelegram("johannes","Heizung auf Anwesenheitsmodus geschaltet")
                    logInfo("heizung","Heizung auf Anwesenheitsmodus geschaltet")
                    return;
                }
            }
            tHeizung.reschedule(now.plusSeconds(1))
        ])
    if(Heizung_Betriebsart.state as Number == 2)
        tHeizung = createTimer(now,[|
            iCounter += 1
            logInfo("heizung","Heizung Schritt {} ",iCounter)
            switch iCounter {
                case 1: Heizung_KanalA_Betriebsart.sendCommand(2) //Wohnzimmer
                case 2: Heizung_KanalB_Betriebsart.sendCommand(2) //Küche
                case 3: Heizung_KanalC_Betriebsart.sendCommand(2) //Flur EG
                case 4: Heizung_KanalH_Betriebsart.sendCommand(2) //Gäste WC
                case 5: Heizung_KanalD_Betriebsart.sendCommand(2) //Kinderzimmer
                case 6: Heizung_KanalE_Betriebsart.sendCommand(2) //Schlafzimmer
                case 7: Heizung_KanalF_Betriebsart.sendCommand(2) //Badezimmer
                case 8: Heizung_KanalG_Betriebsart.sendCommand(2) //Speicher
                default: {
                    sendTelegram("johannes","Heizung auf Abwesenheitsmodus geschaltet")
                    logInfo("heizung","Heizung auf Abwesenheitsmodus geschaltet")
                    return;
                }
            }
            tHeizung.reschedule(now.plusSeconds(1))
        ])
//...
end

To avoid multiple lists of more or less the same commands, I would consider to use maps and groups.
The rule above should count up from 1 to 9, each time it counts up, a (different) command is sent to the bus.
Each time the timer is executed, the timer is rescheduled, only the last step will not, as the code is stopped by return;

2 Likes

Thank you Udo, I will give it a try!

Thank you, Rich and all other friends for the issue, really interesting

I had a rule with Thread::sleep() and it is now time to review it with timers
Now I realize that it could be dangerous against the architecture of the openhab machine

So thank you to your suggestions, I tried to set up an environment to test new design pattern

I have only one item to drive my automation

Switch timerTest

if it is ON I need to make some stuff every 3 seconds
if it is OFF, I don’t need to do anything

This is my rule :

var Integer tick = 0
var Timer myTimer = null

rule "Timer Rule"

when Item timerTest changed 
    
then

     logInfo( "Timer Rule" , "rule triggered - timerTest = " + timerTest.state)       
       
     if(myTimer !== null) 
       myTimer = null;
     
     // initiate the environment
     tick = 0
     
     logInfo( "Timer Rule" , "---- create the timer ---")
   
     myTimer = createTimer(now.plusSeconds(3), [ |
        
        logInfo("Timer Rule","==== TIMER WAKE ON")     
  		if (timerTest.state == OFF) {
       		myTimer = null;
       		logInfo( "Timer Rule" , "do not reschedule it anymore")
            }
        else
 		  {
 		  	// do some stuff here bla bla
 		  	tick = tick + 1
 		  	logInfo( "Timer Rule" , "***** do some stuff here bla bla - tick = " + tick)
 		  	myTimer.reschedule(now.plusSeconds(3))
 		  	logInfo( "Timer Rule" , "rescheduled")
 		  	}
 		
        logInfo("Timer Rule","==== TIMER END")     
    	
    	])
    	
	logInfo( "Timer Rule" , "---- end of the rule ---")
   	   
end


So as I expected

  • the rule is executed immediately and the createTimer doesn’t stop the execution
  • the code in the createTimer brackets is executed as soon as the timer is due
  • the scope of the code in the createTimer brackets is the same of the rule

the trace result is this:

2019-01-06 22:36:37.066 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'timer.rules'
2019-01-06 22:36:40.162 [ome.event.ItemCommandEvent] - Item 'timerTest' received command ON
2019-01-06 22:36:40.180 [vent.ItemStateChangedEvent] - timerTest changed from OFF to ON

2019-01-06 22:36:40.942 [INFO ] [se.smarthome.model.script.Timer Rule] - rule triggered - timerTest = ON
2019-01-06 22:36:40.949 [INFO ] [se.smarthome.model.script.Timer Rule] - ---- create the timer ---
2019-01-06 22:36:40.966 [INFO ] [se.smarthome.model.script.Timer Rule] - ---- end of the rule ---
2019-01-06 22:36:43.959 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:43.981 [INFO ] [se.smarthome.model.script.Timer Rule] - ***** do some stuff here bla bla - tick = 1
2019-01-06 22:36:43.995 [INFO ] [se.smarthome.model.script.Timer Rule] - rescheduled
2019-01-06 22:36:44.002 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END
2019-01-06 22:36:46.994 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:47.014 [INFO ] [se.smarthome.model.script.Timer Rule] - ***** do some stuff here bla bla - tick = 2
2019-01-06 22:36:47.028 [INFO ] [se.smarthome.model.script.Timer Rule] - rescheduled
2019-01-06 22:36:47.034 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END
2019-01-06 22:36:50.026 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:50.047 [INFO ] [se.smarthome.model.script.Timer Rule] - ***** do some stuff here bla bla - tick = 3
2019-01-06 22:36:50.059 [INFO ] [se.smarthome.model.script.Timer Rule] - rescheduled
2019-01-06 22:36:50.066 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END
2019-01-06 22:36:53.058 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:53.080 [INFO ] [se.smarthome.model.script.Timer Rule] - ***** do some stuff here bla bla - tick = 4
2019-01-06 22:36:53.112 [INFO ] [se.smarthome.model.script.Timer Rule] - rescheduled
2019-01-06 22:36:53.119 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END

2019-01-06 22:36:53.951 [ome.event.ItemCommandEvent] - Item 'timerTest' received command OFF
2019-01-06 22:36:53.972 [vent.ItemStateChangedEvent] - timerTest changed from ON to OFF

2019-01-06 22:36:53.985 [INFO ] [se.smarthome.model.script.Timer Rule] - rule triggered - timerTest = OFF
2019-01-06 22:36:53.997 [INFO ] [se.smarthome.model.script.Timer Rule] - ---- create the timer ---
2019-01-06 22:36:54.016 [INFO ] [se.smarthome.model.script.Timer Rule] - ---- end of the rule ---
2019-01-06 22:36:56.107 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:56.119 [INFO ] [se.smarthome.model.script.Timer Rule] - do not reschedule it anymore
2019-01-06 22:36:56.128 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END
2019-01-06 22:36:57.005 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER WAKE ON
2019-01-06 22:36:57.014 [INFO ] [se.smarthome.model.script.Timer Rule] - do not reschedule it anymore
2019-01-06 22:36:57.019 [INFO ] [se.smarthome.model.script.Timer Rule] - ==== TIMER END

but my problem is when I disimiss the timer
As you can see in the last lines of the trace, there is an extra execution of the code in the timer bracket, althought I didn’t reschedule it anymore
22:36:56.119 line didn’t retrigger the timer, so why I have an other execution on 22:36:57.005?

can anybody help me to understand what is wrong in my code?

As you do an extra scheduling, no wonder… :wink:

Your rule is: Every time the item changes, delete the pointer to the timer. Then create a timer 3 seconds in future. You kill the pointer, but not the timer itself. By setting myTimer to null, the timer isn’t stopped! Please tryout this one:

var Integer tick = 0
var Timer myTimer = null

rule "Timer Rule"
when
    Item timerTest changed 
then
    logInfo( "Timer Rule" , "rule triggered - timerTest = " + timerTest.state)       
    myTimer?.cancel                                                            // stop running timer
    if(timerTest.state == ON) {                                                // only schedule timer if switched to on
        tick = 0                                                               // initiate the environment
        logInfo( "Timer Rule" , "---- create the timer ---")
        myTimer = createTimer(now.plusSeconds(3), [ |
            logInfo("Timer Rule","==== TIMER WAKE ON")     
            if (timerTest.state == OFF) {
                myTimer = null
                logInfo( "Timer Rule" , "do not reschedule it anymore")
            } else {
                // do some stuff here bla bla
                tick = tick + 1
                logInfo( "Timer Rule" , "***** do some stuff here bla bla - tick = " + tick)
                myTimer.reschedule(now.plusSeconds(3))
                logInfo( "Timer Rule" , "rescheduled")
            }
            logInfo("Timer Rule","==== TIMER END")     
        ])
    }
    logInfo( "Timer Rule" , "---- end of the rule ---")
end

Of course as the timer is immediately cancelled, the if-part isn’t necessary…

var Integer tick = 0
var Timer myTimer = null

rule "Timer Rule"
when
    Item timerTest changed 
then
    logInfo( "Timer Rule" , "rule triggered - timerTest = " + timerTest.state)       
    myTimer?.cancel                                                            // stop running timer
    if(timerTest.state == ON) {                                                // only schedule timer if switched to on
        tick = 0                                                               // initiate the environment
        logInfo( "Timer Rule" , "---- create the timer ---")
        myTimer = createTimer(now.plusSeconds(3), [ |
            logInfo("Timer Rule","==== TIMER WAKE ON")     
            // do some stuff here bla bla
            tick = tick + 1
            logInfo( "Timer Rule" , "***** do some stuff here bla bla - tick = " + tick)
            myTimer.reschedule(now.plusSeconds(3))
            logInfo( "Timer Rule" , "rescheduled")
            logInfo("Timer Rule","==== TIMER END")     
        ])
    }
    logInfo( "Timer Rule" , "---- end of the rule ---")
end
1 Like

Udo, great, thank you

It runs!!
I will post the final solution for my PWM timer as soon as I close the debug

only another question, what is the meaning of the question mark in mytimer?.cancel
I used it and I’m surprised it runs… I don’t know very well the syntax of Xtend

myTimer?.cancel

is the same as

if (myTimer !== null) myTimer.cancel