Overview of expectable command latency on different hardware?

Hello Community!

I recently tried out openhab on an old RPI B i had still laying around and at the first glance it seemd to run fine. But i noticed horrible command latency of about 1 second from openhab receiving a PIR event until actually sending out the command to switch on a light… Deploying the installation for test on my fileserver (which does not run 24/7 though) resolved the latency issues.

So i am wondering if there is some overview about the different latencys to be expected on different hardware? I dont wanna buy e.g .an RPi2 and end up with the same issues.

Thanks in advance.

I don’t know of any overview like that. It seems the RPi 2 is a relatively common host for openHAB based on postings in this forum. That’s what I use. However, latency can be affected by many different factors like the bindings and hardware you are using, the network configuration, the file system media, other services running on the host, the version of the operating system and on and on.

Such an overview is virtually impossible to create. Let’s look at some of the basics, though.

The Pi is not exactly a speed demon, but can be made reasonably efficient. Do the logs report anything ‘out of the ordinary’ when this ‘slow processing’ occurs? Are there any other jobs active on the box, in other words, what is the performance of the machine? As far as I know all Pi’s (at least the older ones) have single core CPU’s, and the NIC for example can stress it quite a bit when pushing/pulling data. Also, if you’re running a ‘regular Pi distro’ they’re often full of stuff you don’t want/need running, and there’s plenty of room for optimization.

Out of curiosity: From your story I gather that you have a PIR module attached to the Pi via GPIO or USB. Did you connect this to your fileserver for testing as well? What is the command to turn on the light? RF dongle, HTTP binding, more GPIO… ?

Cheers,

Pel

Hello again,

thanks for the responses so far. To specify my setup. The RPI is only running raspbian with openhab. There is no other service running on it. Openhab is connected via MQTT to a MySensors network. The openhab installation is really simple at all. The only rule i have set up so far is to turn on the light when PIR motion is deteced and turn it off 2 minutes afterwards.

@steve: what latency are you seeing? Just for me to know as a landmark. I don’t agree though that latency is affected about seconds by network, bindings, etc: The arduino does the MQTT processing much faster, with a lot less CPU resources. Should not be a problem for even an RPI at all.
@pelnet: although i am running a untuned distro atm, the processes are all sleeping and doing nothing.

would it help to post script and log?

You can’t really compare a microcontroller with no OS that runs a specific program, i.e. your arduino sketch, to a fully blown OS where there will inevitably be tasks running periodically or in the background to keep the OS going.

Hi,

posting a log is generally a good idea, but it won’t help us in this case unless there’s something exceptional in there which might give us a hint. Raspbian comes with a lot of extras, including X11 and a full-blown desktop. It also comes with some cron jobs that are detrimental to the SD card and system performance at times (updating metadata, cache, etc).

Presuming that your 1s delay is consistent throughout multiple test runs, it might be handy to display the rules involved. Also, what’s the latency on the fileserver?

Also, don’t take this the wrong way, but you can hardly compare the MQTT performance of an ATmega with a Pi. Not only does the ATmega not have an operating system, but the MQTT implementation is very, very spartan, like most implementations of protocols and services for such things. Your Pi is running all that inside a JVM, together with a lot more. It’s like comparing a wheelbarrow to the TGV…

If you’re interested, the ‘real’ way to look at the cause (or at least effect) of the problem would be to open up JMX on the JVM and take a look at the data, metrics and threads.

You can enable JMX by adding the following parameters to your command line/startup script:

-Dcom.sun.management.jmxremote \
-Dcom.sun.management.jmxremote.port=9010 \
-Dcom.sun.management.jmxremote.local.only=false \
-Dcom.sun.management.jmxremote.ssl=false \
-Dcom.sun.management.jmxremote.authenticate=false \
-Djava.rmi.server.hostname=<IP OF BOX HERE>

Do note, however, that JMX itself can incur a performance penalty…

@danielwalters86 Indeed.

Cheers,

Pel

Hello guys,

thanks again for the replies. First, the log:

16:36:04.275 [INFO ] [runtime.busevents :26 ] - node1_light state updated to 12
16:36:04.313 [DEBUG] [m.r.internal.engine.RuleEngine:305 ] - Executing rule ‘kitchen light on’
16:36:04.332 [INFO ] [runtime.busevents :26 ] - node1_contact state updated to CLOSED
16:36:05.305 [INFO ] [runtime.busevents :26 ] - node1_temp state updated to 22.0
16:36:05.323 [INFO ] [runtime.busevents :26 ] - node1_humid state updated to 36.0
16:36:05.486 [INFO ] [runtime.busevents :22 ] - kitchen_light received command ON
16:36:05.503 [DEBUG] [.mqtt.internal.MqttItemBinding:44 ] - Publishing command ON to MyMQTT/2/64/V_LIGHT
16:36:05.524 [DEBUG] [o.i.t.m.i.MqttBrokerConnection:437 ] - Publishing message 13 to topic ‘MyMQTT/2/64/V_LIGHT’
16:36:06.114 [DEBUG] [script.actions.ScriptExecution:131 ] - Scheduled code for execution at 2016-01-10T16:38:06.095+01:00

i am not sure yet how to get the actually MQTT message that updates the contact to CLOSED to show up in the log. But the delay problem should be visible.

and there the rule:

import org.openhab.model.script.actions.Timer

var Timer timer

rule “kitchen light on”
when
Item node1_contact changed from OPEN to CLOSED
then
if (node1_light.state <= 37) {
if (kitchen_light.state == OFF) {
sendCommand(kitchen_light, ON)
}
}

if (kitchen_light.state == ON) {
if (timer != null) {
timer.cancel
timer = null
}

timer = createTimer(now.plusSeconds(120)) [|
  sendCommand(kitchen_light, OFF)
]    

}
end

@pelnet
The delay is around 1s (of course there is some jitter). The fileserver has 100ms delay from “Executing rule …” until “Scheduled code for …”. I know that there is a lot more going on on the PI (JVM, etc.) than on the AVR, but that is why i am asking here: Is the delay to be expected for a RPi? Or is something wrong with my setup and there are tuneables?
Thanks for the JMX hint though. I’ll give it a look if i cant get success by stripping the RPIs OS down from unneeded services (atm its still running the graphical UI, etc.). From your responses i guess that the PI should be a bi faster. And i don’t think that an i3 fileserver is really needed to turn on a light :smile:

OK, well, I can’t really see anything at fault, as in obviously wrong or problematic, either. I also don’t use the MQTT binding, so I can’t really compare your delay to much else. However, if it takes 100ms on an i3, ~1000ms on a Pi sounds about right. I’m pretty sure you could tweak some stuff (like killing X and so on) on the Pi, but I doubt you’ll get it to the 100ms marker.

Of course this is wild, abstract speculation, but judging by the timestamp on the first message of your log (node1_light state updated to 12), you have a pretty active bus. Reducing the general speed, especially of items that are polled, can improve responsiveness.

I have an RRD for keeping track of the ‘bus op/s’ or ‘logged operations per second’ for my own setup.

LOAD=`tail -n0 -f /mnt/openhab/logs/events.log>/tmp/tmp.log & sleep 3; kill $! ; wc -l /tmp/tmp.log | cut -c-2`
/usr/bin/rrdupdate BUS_ACTIVITY.rrd N:$LOAD

So, in a nutshell, if you want lightning performance (and some headroom), a Pi is maybe not the most optimal choice. If you’re looking something small and energy saving, you could look at an MSI Windbox or maybe a Brix, Intel NUC, etc.

That question is very general. My general answer is that I don’t see horrible or unacceptable latency with an RPi 2 Model B (@pelnet, this board has a quad core processor).

Your original post said “about a second”, which could mean less than a second. By network, I don’t mean only Ethernet. You did not specify how the motion sensor, the PI and the light switch were communicating. Some transport layers are more CPU and memory intensive than others. The same is true for various binding implementations.

In any case, I’ve seen reports here from others that the older RPi boards could be sluggish when running openHAB. The forums have a search function that might help locate some of that information.

Perhaps it makes sense to disconnect command from sensor and check latency separately?
E.g. for PIR you just look into Openhab App to see how fast the item changes it state.
For command you can do the same - toggle light command from OpenHAB app.
Offcourse my setup is different than yours, but latency is the first thing I checked on my RPI2 + OH + Z-wave Installation. And for commands it is not more than 0.1-0.2 seconds. For PIR sensor it’s about 0,5s.

@steve1
Look e.g. at games. They do far more processing and run smoothly. I think if really the processing of layers, etc. is the bottleneck in OH, there shall be a lot of room for optimization.

But anyway. I want to thank everyone who tried to help. My issue more or less solved itself by upgrading to OH 1.8. I see a long delay for the first few switches, after that it seems to settle and the delay is more or less 200-300ms, which is perfectly acceptable for me.

That’s good to hear. Is that still with the older Raspberry Pi? I’d be interested in knowing which optimizations in 1.8 helped the situation. I wasn’t aware of any major ones.

My openHAB installation uses about 450 MB of virtual memory (~250 MB real memory). That’s fine for an RPi 2 with 1 GB of RAM but would probably cause some VM thrashing with only 512 MB of RAM. A game written in Java and consuming 450 MB of memory would probably also be sluggish on an older RPi. However, I agree that a single-purpose game app would typically be more optimized than a general purpose framework like openHAB.

The “warm up” behavior sounds like it could be Java JIT compilation the first time the code is executed. I’d expect a quad core RPi 2B would execute the JIT compilation somewhat faster too.

@steve1

Sorry for replying so late. I was on a business trip. Yeah it’s still with the same old RPI. For the moment OH takes about 230MB virtual memory and only 96MB real memory on it. But as i said it is not really doing anything yet because i didn’t want to waste any time with complicated things as long as the easy ones are not running smoothly.

I’ve enabled jmx but there don’t seem to be any openhab specific metrics. Only metrics exposed by the JVM itself which are useful but not sufficient to detect issue and correlate them with memory pressure etc.

Would be cool to have “RED” monitoring for all operations in openhab: Number of Requests, number of Errors and Duration for the operation.

Hi there,

JMX usability always depends on the design and nature of the application. I agree with you that it’s not ideal for all scenarios, but I’ve managed to figure out a couple of issues that way.

Looking at this from a sysadmin perspective, you mentioned a number of metrics:

Number of Requests:

Not quite sure what you mean here. I, for example, proxy all HTTP traffic via Apache/HAproxy. Both these applications give you excellent insight into these and more metrics. If you mean the number of updates/commands on the bus, see Failover and Fault Tolerant!

Number of Errors:

If you’re referring to HTTP errors, see above. If you’re referring to ‘openhab errors’, then take a look at

    <appender name="FILE" class="ch.qos.logback.core.FileAppender">
            <file>/var/log/openhab.log</file>
            <encoder>
                    <pattern>%d{HH:mm:ss.SSS} %-5level %logger{30}[:%line]- %msg%n%ex{5}</pattern>
            </encoder>
    </appender>

in your logback.xml.

Duration for the operation:

I’m assuming you’re referring to the cycle of submitting a command to the bus, it being executed, and the operation finishing. I can’t really think of a decent way of getting that info, if you are unable to weedle it out of JMX (which is not going to be easy). Maybe one of the devs could provide more insight…

Cheers,

PelliX

With requests I meant all kind of internal operations. Whether it’s triggering items or internal operations. Errors would be again errors happening during these operations and duration the duration of such operations.
I’m not very familiar with openhab2 but if the bus is some sort of queue, jmx stats for the queue length would be useful too.

Just some general thoughs. I’m quite happy with openhab2 and don’t need this. Just thinking it would be useful for debugging such issues. I’m one of the Prometheus maintainers and therefor have some soft spot for metrics.
This is what I got out of openhab2 already:

(If somebody wants to setup the same, get prometheus and the jmx javaagent exporter and run openhab2 with EXTRA_JAVA_OPTS="-javaagent:/opt/jmx_exporter/jmx_exporter.jar=9234:/opt/jmx_exporter/config.yaml")

If this is still of interest to somebody, it might be worth looking at this new bundle we just released: