My rule brings OH to CPU usage >100%

chris4789 · October 20, 2019, 7:29pm

I am still a beginner and far a way from a coder …
I searched around and copied code from the web to get my drier working, based on a formula to get dew point.

I am running OH 2.5M3 on a Rpi 3 without any problem.
But when I activate following rule OH goes to >100% CPU usage and the log is late with entries from rules for about 10 minutes.
So it is not possible for me to react on infos from log.

Following the rule:

import java.lang.Math

rule "Drier WG"
when 
      Item Humidity_WG changed
then
    double Dewpoint = 243.5*(Math::log((Humidity_WG.state/100))+((17.67*Temperatur_WG.state)/(243.5+Temperatur_WG.state)))/(17.67-Math::log((Humidity_WG.state/100))-((17.67*Temperatur_WG.state)/(243.5+Temperatur_WG.state)))
    if((Temperatur_WG.state+localCurrentTemperature)/2 <= Dewpoint)
        {
        sendCommand(DrierWG, ON)
    }
    else if((Temperatur_WG+localCurrentTemperature)/2 > Dewpoint+2)
        {  
        sendCommand(DrierWG, OFF)
    }
end

Is it possible that the formula could bring the rules engine to such a high load?
Am I totally wrong with my approach?

The log shows an entry:

2019-10-20 18:57:18.807 [INFO ] [el.core.internal.ModelRepositoryImpl] - Validation issues found in configuration model 'DrierWG.rules', using it anyway:

This expression is not allowed in this context, since it doesn't cause any side effects.

2019-10-20 18:57:18.814 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'DrierWG.rules'

But just once, then OH is on >100% CPU load.

Any help or advise would be very much appreciated!

mstormi · October 20, 2019, 8:23pm

You’re probably editing your rule file in place, and every save causes a recompile run, queuing up.
So change your editing habits.

rossko57 · October 20, 2019, 9:50pm

I think you want a var or val in there, and generally it’s best to use Numbers in rules

var Number Dewpoint = 243.5*( ...

5iver · October 21, 2019, 7:43am

Is localCurrentTemperature an Item it’s global variable? If an Item, then you’ll need its state. Also, If it or Temperatur_WG use Units of Measure, their states will need conversion to a Number before being used in arithmetic.

chris4789 · October 21, 2019, 8:40am

Thanks to all for your assistance!
I will check this out at evening.

@5iver “localCurrentTemperature” is an item from OWM, so I will add the .state, thanks for this.
All other items using UoM, so I will convert to Number accordingly.

@mstormi I was not aware that compilation of such a little rule could effect such a high load.
However, will try in future to avoid multiple rule changes within a short time.

mstormi · October 21, 2019, 9:01am

You didn’t get the point.
It’s with ANY rule and it does not matter how long it takes you to change it.
It’s that you must not do intermediate saves, so better copy the rule off to somewhere, edit it there and copy it back only when you’re fully done editing.

chris4789 · October 22, 2019, 5:10pm

I did as suggested but the load is still more than 100% and the rules engine is blocked for minutes.

I got a new error message:

2019-10-22 18:56:53.497 [ERROR] [ntime.internal.engine.RuleEngineImpl] - Rule 'Trockner WG': An error occurred during the script execution: Could not invoke method: java.lang.Math.log(double) on instance: null

No idea what this means …

I guess my approach is not working, maybe anyone has another working solution?
I simply want to avoid condensed water on the glasses in my winter garden by calculating the dew point roughly

rlkoshak · October 22, 2019, 5:20pm

The error is in a Rule names ‘Trockner WG’

There was an error

You have a call to Math::log(something) in this Rule and something is not of type double.

kriznik · October 22, 2019, 6:33pm

this is absolutely not true at all…
why are you spreading such advices?
it does sounds same as “you must not restart your system with system command reboot, because you are doing it wrong” …
that reminds me “you are holding your iphone in the wrong way as we designed it”

Editing rules in place is completely fine and OH can handle this just fine (on any of my rpi or production machine). So issue is definitely somewhere else than this.

mstormi · October 22, 2019, 7:10pm

Oh, it is. And I’m spreading advice because only few people know about these inner workings of OH and keep doing intermediate saves because they are not aware of what that is triggering.
Every save (inside the rules or items directory) triggers a rule recompilation that - depending on your rule and linked config - may be fast or take up to even some minutes.
I didn’t say editing in place is a condition per se but it’s a prerequisite. It also depends on how often you save your (draft) rule file, depends on if that’s syntactically correct (broken syntax compiles stop fast), how many items it applies to and of course how long it takes to compile your file.
I’ve got a 1K line rules file that to compile takes ~100 seconds on a RPi.
If you yourself have few items or small files it’s probably just some seconds or less and you didn’t notice it happens on your system, too. Obviously depends on HW speed, too.
But it happens in all OH installs.
And if you save again while a compile is still running, this is queuing up.

chris4789 · October 22, 2019, 7:26pm

Thanks for commenting.
Following the two items concerned:

Number Luftfeuchte_WG "Luftfeuchtesensor WG [%f %%]" {channel="zwave:device:Razberry2:node6:sensor_relhumidity"}

and

Number:Temperature Temperatur_WG "Temperatur WG [%.1f °C]" {channel="zwave:device:Razberry2:node6:sensor_temperature"}

Both are of definded as type Number which should fit to “double”.

rossko57 · October 22, 2019, 7:34pm

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?

chris4789 · October 22, 2019, 7:51pm

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 …

rossko57 · October 22, 2019, 8:01pm

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.

5iver · October 22, 2019, 8:13pm

This is what I was meaning ! 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())))

rlkoshak · October 22, 2019, 8:38pm

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) + ...

chris4789 · October 22, 2019, 9:14pm

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?

5iver · October 22, 2019, 9:33pm

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")

rlkoshak · October 22, 2019, 9:54pm

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.

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.

5iver · October 22, 2019, 11:16pm

I wasn’t meaning the run times were long… just the load . 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…

I’ve never used it, but there is one built into Python… 26.6. timeit — Measure execution time of small code snippets — Python 2.7.18 documentation.