My rule brings OH to CPU usage >100%

Well, one is a “plain ordinary” Number and one is a Quantity Type with UoM.
You will need to treat differently in rules.

May we see the rule after recent changes?

Yes of course:

import java.lang.Math

rule "Trockner WG"
when 
      Item Luftfeuchte_WG changed
then
        logInfo("TrocknerWG.rules", "Aktueller Taupunkt: ", Luftfeuchte_WG)
if (Luftfeuchte_WG.state != null)
{
    var Number Taupunkt = 243.5*(Math::log((Luftfeuchte_WG.state/100))+((17.67*Temperatur_WG.state)/(243.5+(Temperatur_WG.state))))/(17.67-Math::log((Luftfeuchte_WG.state/100))-((17.67*Temperatur_WG.state)/(243.5+Temperatur_WG.state)))
    if (((Temperatur_WG.state)+(localCurrentTemperature.state))/2 <= Taupunkt) {
        sendCommand(TrocknerWG, ON)
    }
    else if (((Temperatur_WG.state)+(localCurrentTemperature.state))/2 > Taupunkt+2) {  
        sendCommand(TrocknerWG, OFF)
    }
    }
end

I changed a lot and it is in my natural language german, so I hope you can read it properly.
Sorry, but “Plain Ordinary” and “Quantity Type” is not within my range of knowledge …

Plain,ordinary Number Item
Number Luftfeuchte_WG
This one will have a state like 22.5

Number Item with UoM - units of measurement
Number:Temperature Temperatur_WG
This one will have a state like 17.5°C
The unit is part of the state, so you need to take steps to get just the numeric part if you want to do maths on it.

This is what I was meaning :slightly_smiling_face:! See if this gets you closer…

var Number Taupunkt = 243.5*(Math::log((Luftfeuchte_WG.state/100))+((17.67*Temperatur_WG.state.floatValue())/(243.5+(Temperatur_WG.state.floatValue()))))/(17.67-Math::log((Luftfeuchte_WG.state/100))-((17.67*Temperatur_WG.state.floatValue())/(243.5+Temperatur_WG.state.floatValue())))

What rossko57 and Scott say is true but there is one other gotcha that might be causing problems here. By default all calculations in OH return a BigDecimal. Math::log requires a primitive double. So, to take Scott’s line of code, you may need to call doubleValue on the result of the divide by 100.

...(Math::log((Luftfeuchte_WG.state/100).doubleValue) + ...
1 Like

Thanks for your comment!
This could explain the entry in log I got a few minutes ago:

2019-10-22 23:03:03.188 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Trockner WG': Unknown variable or command '/'; line 11, column 45, length 24

But I am still struggling with reactions of rules engine.
After enabling of this rule it takes more than 10 minutes until I get a respond.

So, is it possible that the math::log could bring my Rpi to its limit?

In testing this out, I am seeing extremely high load from the use of primitives, and I’m on desktop hardware! So, I used this as an opportunity to do a comparison of the old to new rule engine and it was dramatic… as in immediate (1 ms)! The rules DSL was on the order of minutes.

import math
from org.joda.time import DateTime
start_time = DateTime.now()
Taupunkt = 243.5 * (math.log((items["Virtual_Number_1"].floatValue() / 100.0)) + ((17.67 * items["Current_Temperature"].floatValue())/(243.5 + items["Current_Temperature"].floatValue()))) / (17.67 - math.log(items["Virtual_Number_1"].floatValue() / 100.0) - (17.67 * items["Current_Temperature"].floatValue() / (243.5 + items["Current_Temperature"].floatValue())))
log.warn(u"{}, {} ms".format(Taupunkt, DateTime.now().millis - start_time.millis))

@chris4789, if you can setup Jython, I’m sure this is something that will help you. I converted your rule, but I have only tested the Taupunkt variable.

import math
from core.rules import rule
from core.triggers. import when

@rule("Trockner WG")
@when("Item Luftfeuchte_WG changed")
def calculate_dewpoint(event):
    calculate_dewpoint.log.warn("Aktueller Taupunkt: {}".format(event.itemState))
    if not isinstance(items["Luftfeuchte_WG"], UnDefType):
        Taupunkt = 243.5 * (math.log((items["Luftfeuchte_WG"].floatValue() / 100.0)) + ((17.67 * items["Temperatur_WG"].floatValue())/(243.5 + items["Temperatur_WG"].floatValue()))) / (17.67 - math.log(items["Luftfeuchte_WG"].floatValue() / 100.0) - (17.67 * items["Temperatur_WG"].floatValue() / (243.5 + items["Temperatur_WG"].floatValue())))
        if (items["Temperatur_WG"].floatValue() + items["localCurrentTemperature"].floatValue()) / 2.0 <= Taupunkt:
            events.sendCommand("TrocknerWG", "ON")
        elif (items["Temperatur_WG"].floatValue() + items["localCurrentTemperature"].floatValue()) / 2.0 > Taupunkt + 2:
            events.sendCommand("TrocknerWG", "OFF")

Indeed, my recommendation is to avoid the use of primitives as much as is possible. But it’s not possible to avoid them completely because Java library classes like Math and even Joda DateTime’s plus/minus functions all require the use of primitives. Constants like the numbers used in the calculations above should be instantiated as BigDecimal for you so it’s the calls to xValue (e.g. floatValue) or defining a var/val explicitly as a primitive that will force the Rules DSL to use primitives.

However, I’ve not seen reports of Rules taking minutes to run. All previous reports had to do with how long it takes to load and parse the Rules (I’ve seen reports of elimination of primitives shaved 15 minutes off of rules load times on an RPi). Once parsed though, the Rules would run just fine. This extended load time can get exacerbated if you are in a tight edit and save loop as your changes are likely to be faster than the machine can load and parse the Rules, hence Markus’s recommendation.

OP is running 2.5 M3 (unless I missed something) so whatever changed happened two+ months ago. I’m surprised there hasn’t been more users reporting the same behavior. And I haven’t watched the PRs that closely, has there been any updates to the Xtend/Xtext libraries in that time frame? That’s about the only place where this problem would reside, and it means we will need to wait for the upstream to fix whatever they broke. :frowning:

This behavior appears to be something new and needs more exploration I think.

I’m actually not seeing this behavior (on the latest snapshot build).

The following Rule:

rule "Test primitives"
when
    System started
then
    val long start = now.millis
    val double num = 100
    val calculation = Math.log(num.doubleValue)
    val long stop = now.millis
    logInfo("Test", "The Rule took " + (stop - start) + " milliseconds to run")
end

Outputs

2019-10-22 15:51:45.094 [INFO ] [.eclipse.smarthome.model.script.Test] - The Rule took 2 milliseconds to run

with no spike in CPU.

So the behavior is not universal which is going to make diagnosing it a bear.

As an aside, there is a third party Weather Calculations Binding that may have this calculation built in.

I could also see calculations like this made as library functions in the Helper Libraries.

I wasn’t meaning the run times were long… just the load :slightly_smiling_face:. I was only using ‘System started’ as the trigger in the DSL.

Your example took 7 ms to load the first save and 1ms to load the second save. Try this one. Saving the file took several minutes and my load went over 4 on a dual core.

import java.lang.Math

rule "Test"
when
    System started
then
    logWarn("Rules", "Test: Start")

    val Taupunkt = 243.5 * (Math::log((Virtual_Number_1.state / 100)) + ((17.67 * Current_Temperature.state.floatValue())/(243.5 + Current_Temperature.state.floatValue()))) / (17.67 - Math::log(Virtual_Number_1.state / 100) - (17.67 * Current_Temperature.state.floatValue() / (243.5 + Current_Temperature.state.floatValue())))
    logWarn("Rules", "Value = {}", Taupunkt)

    logWarn("Rules", "Test: End")
end

I’m not so sure that it’s new. The OP is not reporting that this ever performed differently. I do remember some devs discussing primitives and performance issues. I don’t recall specifics, but I think I remember it being tossed back on the pile as not something that could be easily fixed. The new rule engine works well, so we should just take the old one out back… :exclamation:

I’ve never used it, but there is one built into Python… https://docs.python.org/2/library/timeit.html.

Curious. I have a long winded dewpoint calc rule, cribbed from somewhere - wiil not vouch for accuracy (and welcome impovement)
Ignore the fetch-Item-from-group stuff, I just pasted as-is and added a timer

Note - that I do not have Math imports in this file. Is that contributing??

val Number DewMargin = 1.0  // temp margin for condensation alert

// Dew check
rule "dew check"
when
	Member of gIntHumids changed
then
    val long start = now.millis
	val rootname = triggeringItem.name.split("_").get(1)  // derive partners name
	val tempname = "nm_" + rootname + "_temp"  // derive temp name
	val dewname = "vsw_" + rootname + "_dew"   // derive dew alert
	logInfo("dewcalc", "Seeking " + tempname + " " + dewname)
	val myTemp = gIntTemps.members.findFirst[ i | i.name == tempname ] // get temp item
	val myDew = gDewAlerts.members.findFirst[ j | j.name == dewname ] // get dew item
// THE DEWPOINT CALC
	if (myTemp !== null && myDew !== null) {
		val humidRH = triggeringItem.state as Number
		val tempC = myTemp.state as Number
		val e = 2.71828 // for nat log
		logInfo("dewcalc", "Temp " + tempC.toString + " Humid " + humidRH.toString)
			// Magnus formula
		val Number satvap = 6.112 * Math.pow(e, (17.62 * tempC)/(243.12 + tempC))
		val absvap = (satvap / 100 * humidRH).floatValue // need for the log
		val Number inter = Math.log(absvap/6.112)
		val Number dewpoint = (235 * inter) / (17.1 - inter)
		logInfo("dewcalc", "Dewpoint " + dewpoint.toString +" OutC " + nm_Out_temp.state.toString)
		if (nm_Out_temp.state != NULL) {	// compare to wall temp
			val worrypoint = (nm_Out_temp.state as Number) + DewMargin
			if (dewpoint > worrypoint && myDew.state != ON) {
				logInfo("dewcalc", "Dew alarm " + myDew.name)
				myDew.postUpdate(ON) // set alarm
			} else if ((dewpoint + DewMargin) < worrypoint && myDew.state != OFF) { // with hysteresis
				logInfo("dewcalc", "Dew Okay " + myDew.name)
				myDew.postUpdate(OFF) // clear alarm
			}
		}
	} else {
		logInfo("dewcalc", "CONFIG ERROR matching humid sensor name")
	}
    val long stop = now.millis
    logInfo("Test", "The Rule took " + (stop - start) + " ms to run")
end

Running OH2.4 on Win7 centrino laptop.
No particular issue noted with loading rules file.
Execution times, first and second, 24 and 17mS

2019-10-23 01:32:53.633 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'enviro.rules'
2019-10-23 01:33:00.855 [INFO ] [lipse.smarthome.model.script.dewcalc] - Temp 15.5 Humid 30.0
2019-10-23 01:33:00.864 [INFO ] [lipse.smarthome.model.script.dewcalc] - Dewpoint -2.01572707 OutC 6.01
2019-10-23 01:33:00.870 [INFO ] [.eclipse.smarthome.model.script.Test] - The Rule took 24 ms to run
2019-10-23 01:33:35.795 [INFO ] [lipse.smarthome.model.script.dewcalc] - Temp 15.5 Humid 40.0
2019-10-23 01:33:35.801 [INFO ] [lipse.smarthome.model.script.dewcalc] - Dewpoint 1.93618021 OutC 6.01
2019-10-23 01:33:35.805 [INFO ] [.eclipse.smarthome.model.script.Test] - The Rule took 17 ms to run

Edit - out of curiosity, I moved the timer-begin to after the Item fetching clutter and got 20mS/11mS
Obviously it would be more sluggish on a Pi.

1 Like

OK, I misunderstood, I thought the delay you were reporting was the runtime of the rule. I can confirm with this specific Rule I’m seeing about a 3 minute load time with near 100% CPU on a 2 virtual cpu VM.

And it does totally stack up. If you don’t wait for the rule to be loaded and make additional edits you will be sitting at 100% CPU utilization for a good long time.

This is really good as it gives the maintainers a Rule they can use on just about any machine (it would appear) to reproduce the behavior. Do we know if there has been an issue opened and what it is? I assume this would be in core.

I tend to agree about deprecating Rules DSL but I suspect it’s going to be a long process to make that happen. If this can be fixed it should probably be fixed.

No. You don’t have to import anything from java.lang. When I copied Scott’s version of the Rule I left the import out and it took forever to load with a very high load.

I decided to do a quick test and I think I know why your version doesn’t have the problem but OP’s and Scotts does. When I take the crazy long calculation and break it up into multiple lines, saving the results of smaller pieces of the calculation to a variable like in your Rule the loading problem goes away, or at least is way less noticeable (a few seconds as opposed to three minutes).

rule "Test"
when
    System started
then
    logWarn("Rules", "Test: Start")
    val a = 243.5
    val b = Math::log((vBasement_Light.state as Number).doubleValue / 100)
    val c = (17.67 * (vBasement_Light.state as Number).floatValue())
    val d = (243.5 + (vBasement_Light.state as Number).floatValue())
    val e = 17.67 - Math::log((vBasement_Light.state as Number).floatValue / 100)
    val f = 17.67 * (vBasement_Light.state as Number).floatValue()
    val g = 243.5 + (vBasement_Light.state as Number).floatValue()

    val Taupunkt = a * (b + (c/d)) / (e - (f / g))

//    val Taupunkt = 243.5 * (Math::log((Virtual_Number_1.state / 100)) + ((17.67 * Current_Temperature.state.floatValue())/(243.5 + Current_Temperature.state.floatValue()))) / (17.67 - Math::log(Virtual_Number_1.state / 100) - (17.67 * Current_Temperature.state.floatValue() / (243.5 + Current_Temperature.state.floatValue())))
    logWarn("Rules", "Value = {}", Taupunkt)

    logWarn("Rules", "Test: End")
end

I have no idea if I have the parens in the right place in my conversion but that isn’t the point. I’m not testing for the correct answer, just to see how the parser handles the calculations. And I just some random Number Item in place of the number Items from the original calculations. I just need a number, I’m not after verifying the actual result.

The above Rule took about 5 seconds to load. And it has just as many primitives and just as many calculations as the original. It just doesn’t try to do it all on one line of code.

I suspect that the part of the Rules Parser that checks type at parse time is O(N!) or O(C^N) or something crazy like that (I know, only CS type folks will understand what that means, see https://en.wikipedia.org/wiki/Big_O_notation for details) meaning the more stuff you give it to have to try and figure out type on one line the amount of work required goes through the roof. The problem with using primitives is that the Rules DSL can’t delay the type checking until runtime like it can with Objects so we are forcing it to go down this O(N!) O(C^N) algorithm.

So my recommendation is:

  • Avoid using primitives unless absolutely necessary (e.g. passing them to a method that requires a primitive)
  • Do not convert values to primitives until the absolutely last moment (e.g. keep it as a Number until you actually make the call that requires it to be a primitive)
  • Break up long calculations into multiple lines. Not only is this easier to read, it lowers the value of N for those lines making the job much easier on the parser to verify the types for the lines that use primitives.
  • Don’t edit Rules DSL files in place or at least watch the logs to make sure your previous edits were loaded before making and new saves.
    EDIT:
  • Consider moving to Scripted Automation which does not have this and other problems exhibited by Rules DSL
3 Likes
  • Use the new rule engine :pleading_face:
1 Like

That’s not helpful for people who either have a well established system, or for newcomers relying on the back catalogue of shared rules (for now).

By all means extol the virtues for OH3.

OH makes it easy to start small with a second system just using Items without channel links. You can work on one small bit at a time.

I split the rule as @rlkoshak suggested and the high load is away!
I got the first value:

2019-10-23 19:14:36.033 [INFO ] [rthome.model.script.TrocknerWG.rules] - Value = 16.30693731941898

so this is working fine for me :slightly_smiling_face:

Thanks to all for contributing!

1 Like

I see this differently. If you have a well established system and are trying to add a rule that relies on primitives, there is no reason why you can’t use the new rule engine for just that rule. The rest of your system is untouched and you are helping the community to test and document the new rule engine. By back catalog, I assume you mean the pile of random threads in the forum? The DPs now have Jython examples and the amount of scripted automation in the forum is definitely increasing. For old and newcomers, there is a whole set of documentation available along with the helper libraries, which IMO has more detail about writing rules than the OH docs… and I’m we’re far from done with it.

If we were all neophobes, OH would have died off long ago! BTW, the new rule engine has been around for about 5 years, so it’s really not all that new!

Just to close the loop, it would be nice to post your Rule that is working better.

1 Like

thanks all for your responses. i was having similar questions and your answers were helpful to me. Also this math site guide will enhance your math accuracy to more than 100%. Try using it. It’s for basic math problem to derivatives.

1 Like

Yes of course, will do when I’m home again.
Even it is exactly same as you suggested above, just changed the items.

Following now the full rule:

import java.lang.Math

rule "Trockner WG"
when 
      Item Luftfeuchte_WG changed
then
    val a = 243.5
    val b = Math::log((Luftfeuchte_WG.state as Number).doubleValue / 100)
    val c = (17.67 * (Temperatur_WG.state as Number).floatValue())
    val d = (243.5 + (Temperatur_WG.state as Number).floatValue())
    val e = 17.67 - Math::log((Luftfeuchte_WG.state as Number).floatValue / 100)
    val f = 17.67 * (Temperatur_WG.state as Number).floatValue()
    val g = 243.5 + (Temperatur_WG.state as Number).floatValue()

    val Taupunkt = a * (b + (c/d)) / (e - (f / g))
    logInfo("TrocknerWG.rules", "Taupunkt = {}", Taupunkt)

    if ((((Temperatur_WG.state as Number)+(localCurrentTemperature.state as Number)) / 2 <= Taupunkt) && TrocknerWG.state == OFF) {
        sendCommand(TrocknerWG, ON)
    }
    else if ((((Temperatur_WG.state as Number)+(localCurrentTemperature.state as Number)) / 2 > Taupunkt + 2) && TrocknerWG.state == ON) {  
        sendCommand(TrocknerWG, OFF)
    }
end

I have not checked exactly but it is now loaded within a very short time, far away from the >10min as before :slightly_smiling_face:

Thanks again for this solution!

1 Like