I have been seeing consistent delays of 4-5 seconds when using InsteonPLM to control a light to turn on using a motion sensor. This is too long for my use case (1-2 seconds max). It is very consistent and occurs every time. I have encountered this in Openhab 1.7 and the latest 1.8 (within the past couple days).
I do not get the delay when pairing the motion sensor to the dimmer directly, nor do I get it when using the Insteon Rest API in a standalone C# module I wrote to do the exact same thing. Switching the light on through the Openhab web interface also works without the delay.
My case is very simple: 1 Insteon Motion Sensor (2842-222) and 1 Insteon Dimmer (2477D), using the post-2014 Insteon Hub (2245-222). The rule is very simple:
when
Item entrancewayMotion changed from CLOSED to OPEN
then
sendCommand(entrancewayUpperSwitch, new PercentType(100))
end
I went poking around InsteonPLM to determine the source of the delay. Eventually, I was able to get rid of the delay by commenting out the call to sendExtendedQuery in the OpenedSleepingContactHandler function (insteonplm/internal/device/MessageHandler.java). I donât know what other effects this may have. This cuts the delay down to a more acceptable 1-2 second range, which is about the same as using the REST API and only slightly slower than pairing directly.
Is there another solution to this problem?
Below are the relevant logs from motion sensor OPEN to light turn on. In this case, the light doesnât turn on until 13:17:22:
2016-01-01 13:17:18.098 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01|
2016-01-01 13:17:18.099 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01|
2016-01-01 13:17:18.099 DEBUG o.o.b.i.i.d.MessageDispatcher[:70]- all link message is no duplicate: true/true
2016-01-01 13:17:18.099 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 37.B3.1E:MotionSensorData->NoOpMsgHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01|
2016-01-01 13:17:18.099 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01|
2016-01-01 13:17:18.100 DEBUG o.o.b.i.i.d.MessageDispatcher[:70]- all link message is no duplicate: true/true
2016-01-01 13:17:18.100 DEBUG o.o.b.i.i.d.MessageDispatcher[:72]- 37.B3.1E:WirelessMotionSensorContact->OpenedSleepingContactHandler cmd1:0x11 group 1/1:IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:00.00.01|messageFlags:0xCF=ALL_LINK_BROADCAST:3:3|command1:0x11|command2:0x01| > 2016-01-01 13:17:18.100 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 37.B3.1E:WirelessMotionSensorContact publishing: OPEN
2016-01-01 13:17:18.101 DEBUG o.o.b.i.i.device.InsteonDevice[:379]- qe taken off direct: WirelessMotionSensorContact(1:1:5) OUT:Cmd:0x62|toAddress:37.B3.1E|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|
2016-01-01 13:17:18.101 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 37.B3.1E:GenericLastTime publishing: 2016-01-01T13:17:18
2016-01-01 13:17:18.101 DEBUG o.o.b.i.i.device.InsteonDevice[:399]- next request queue processed in 500 msec, quiettime = 500
2016-01-01 13:17:18.101 DEBUG o.o.b.i.internal.driver.Port[:382]- writing (500): OUT:Cmd:0x62|toAddress:37.B3.1E|messageFlags:0x1F=DIRECT:3:3|command1:0x2E|command2:0x00|userData1:0x00|userData2:0x00|userData3:0x00|userData4:0x00|userData5:0x00|userData6:0x00|userData7:0x00|userData8:0x00|userData9:0x00|userData10:0x00|userData11:0x00|userData12:0x00|userData13:0x00|userData14:0xD2|
2016-01-01 13:17:18.173 INFO o.o.b.i.InsteonPLMActiveBinding[:125]- Item: entrancewayUpperSwitch got command 100
2016-01-01 13:17:18.173 DEBUG o.o.b.i.i.device.InsteonDevice[:168]- processing command 100 features: 4
2016-01-01 13:17:18.175 DEBUG o.o.b.i.i.d.CommandHandler[:462]- changing level of 3C.6A.D7 to 100
2016-01-01 13:17:18.175 INFO o.o.b.i.i.d.CommandHandler[:468]- PercentHandler: sent msg to set 3C.6A.D7 to 255
2016-01-01 13:17:18.176 DEBUG o.o.b.i.i.device.InsteonDevice[:379]- qe taken off direct: GenericDimmer(1:3:8) OUT:Cmd:0x62|toAddress:3C.6A.D7|messageFlags:0x0F=DIRECT:3:3|command1:0x11|command2:0xFF|
2016-01-01 13:17:18.176 DEBUG o.o.b.i.i.device.InsteonDevice[:399]- next request queue processed in 500 msec, quiettime = 500
2016-01-01 13:17:18.600 DEBUG o.o.b.i.i.d.RequestQueueManager[:132]- device queue for 37.B3.1E is empty!
2016-01-01 13:17:18.675 DEBUG o.o.b.i.i.d.RequestQueueManager[:132]- device queue for 3C.6A.D7 is empty!
2016-01-01 13:17:19.608 DEBUG o.o.b.i.internal.driver.Port[:382]- writing (500): OUT:Cmd:0x62|toAddress:3C.6A.D7|messageFlags:0x0F=DIRECT:3:3|command1:0x11|command2:0xFF|
2016-01-01 13:17:22.139 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x50|fromAddress:3C.6A.D7|toAddress:39.18.C0|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x11|command2:0xFF|
2016-01-01 13:17:22.140 DEBUG o.o.b.i.i.d.MessageDispatcher[:134]- 3C.6A.D7:GenericDimmer DIRECT_ACK: q:QUERY_PENDING cmd: 80
2016-01-01 13:17:22.140 DEBUG o.o.b.i.i.d.MessageDispatcher[:139]- changing key to 0x19 for msg IN:Cmd:0x50|fromAddress:3C.6A.D7|toAddress:39.18.C0|messageFlags:0x2F=ACK_OF_DIRECT:3:3|command1:0x11|command2:0xFF|
2016-01-01 13:17:22.140 INFO o.o.b.i.i.d.MessageHandler[:472]- DimmerRequestReplyHandler: set device 3C.6A.D7 to level 100 > 2016-01-01 13:17:22.140 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 3C.6A.D7:GenericDimmer publishing: 100
2016-01-01 13:17:22.141 DEBUG o.o.b.i.i.d.MessageDispatcher[:159]- defdisp: 3C.6A.D7:GenericDimmer set status to: QUERY_ANSWERED
2016-01-01 13:17:22.141 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 3C.6A.D7:GenericLastTime publishing: 2016-01-01T13:17:22
2016-01-01 13:17:22.142 DEBUG o.o.b.i.InsteonPLMActiveBinding[:581]- got msg: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:39.18.C0|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2016-01-01 13:17:22.142 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:39.18.C0|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2016-01-01 13:17:22.142 DEBUG o.o.b.i.i.d.MessageDispatcher[:68]- all link message: IN:Cmd:0x50|fromAddress:37.B3.1E|toAddress:39.18.C0|messageFlags:0x4B=ALL_LINK_CLEANUP:3:2|command1:0x11|command2:0x01|
2016-01-01 13:17:22.142 DEBUG o.o.b.i.i.device.DeviceFeature[:264]- 37.B3.1E:GenericLastTime publishing: 2016-01-01T13:17:22
Is there a delay in the log or in the light actually turning on? The hub itself is polled, and I think itâs a default of 1 second, so this will add some delay. In another conversation @Bernd_Pfrommer commented that there are sometimes unexplained long delays with the hub between the request and response which appears is happening here:
The delay is in the light actually turning on (doesnât turn on until 13:17:22 in this case).
Whatâs strange is that by removing the âextended queryâ made to the motion sensor that occurs immediately after receiving the OPEN event, the delay is much shorter (< 2 sec). I think the extended query is used for getting the battery/light level from the motion sensor, which makes sense b/c I noticed the battery/light level only getting updated when there is motion sensor activity.
Could it be waiting for a response to the motion sensor battery/light level query before it sends out the dimmer ON command?
FWIW, I havenât see these type of delays in my Insteon motion control setup (1.8.0-SNAPSHOT). However, I donât use a hub and I control the bulbs directly from openHAB (vs. a 2477D dimmer).
OK, I know whatâs going on⊠it took me awhile to realize that the message writer (Port.java) waits for a response from every single message it sends out. The writer sits and waits after every message send and does not send another one until it gets a response from the first. In addition, it waits another 0.5 sec after receiving the response until sending the next message.
My long delay is coming from the motion sensor battery/light level query that it sends before the light ON command. It takes over 1 second for the data to come back from the motion sensor. This gives me an additional 1.5+ sec delay before actually sending the light ON command!
So this is the rough timeline:
t=0.0: Receive motion sensor OPEN event
t=0.0+: Queue up battery/light sensor query t=0.0+: Queue up light ON command
t=0.0+: Dequeue and send battery/light sensor query
Wait for motion sensor responseâŠ
t=1.0: Receive motion sensor battery/light response
Writer sleep for 0.5s⊠t=1.5: Dequeue and send light ON command
Shortly after, the light is on!
This explains all the strange behavior I was seeing. To eliminate the delays, I can comment out the light/battery query that is performed every motion sensor event for a quick fix, and maybe eliminating the 500ms writer âquiet timeâ.
@steve1 Thanks for the info, I thought it was odd that I couldnât find anyone with a similar issue. Itâs pretty obvious and occurs every time for me. I wonder if my motion sensor is abnormally slow to respond. I have another sensor still in the box I can try out.
A new motion sensor yields the same result. The battery/light query must be slow coming from the hub.
Ideally, the communication to the hub would be more asynchronous and not have to worry as much about reliability, since it uses HTTP/TCP instead of the serial PLM. Iâve had success writing a simple Openhab binding using the Insteon REST API to get motion events and control lights with acceptable delays. Implementation-wise itâs certainly much simpler, but it also means youâre dependent on Insteonâs servers and a working internet connection.
Your best bet might be to switch to a PLM which uses a serial port instead of HTTP polling. I know that @Bernd_Pfrommer spent considerable time getting the binding working with the hub, and Iâm sure thereâs a reason itâs not more asynchronous.
The motion sensor is queried immediately when it reports motion because thatâs the only time it is actually awake. It goes to sleep a few seconds later, so (carpe diem) the binding queries it right away. These extended queries are slow, both at the insteon level, and of course the 1s poll time for the 2014 hub doesnât help either.
If you reduce the 500ms back-to-back time you are likely to get more dropped messages, at least on the PLM (and the hub has one of those built in). The message gets ackâed by the modem, but disappears on the insteon network without trace, as if you never sent it.
Whatâs the fix? For sure would be nice to send out the query only if somebody actually has hooked up an item to the battery level and light level features. Right now we query regardless of that.
One option would be to install a poll handler and call doPoll(delay) on the device, and explore how long a delay we can get away with. The poll message should only actually execute if an item is hooked up to the âdataâ field. So then you should have no delay unless you actually are interested in âdataâ. Even if you are, the poll may execute after your rule, but Iâm not sure about the âdelayâ factor. That was always a bit of a hack.
So without having time to really do it, I suggest replacing
sendExtendedQuery(f, (byte)0x2e, (byte) 00);
in the sleeping handlers with a call to device.doPoll(xx);
Thanks Bernd. I didnât know the motion sensor data canât be queried unless it is woken up by motion. I may give your solution a shot. I donât actually need the battery/light data, so just eliminating the query works for me.
I know this string is a bit stale but I am seeing the same type of delays (3-4 secs). But, I am using the InsteonPLM not the HUB. Any thoughts/fixes other than eliminating the battery/light data.
I do not have a development environment setup. My insteon system is currently consists of two dimmers, two micro on/off modules and two motion sensors. I am still in the âproof of conceptâ stage. I have to prove the system works and is reliable before I get the âgo aheadâ to expand into the rest of the house. So, I am willing to make any modifications/improvement that will improve the WAF (Wife Acceptability Factor).
Please explain the modification a bit further. Where is this âsendExtendedQuery(f, (byte)0x2e, (byte) 00)â found in the configuration files. Any suggestions what number to use for âdevice.doPoll(xx)â.
Also, I presume that these modifications cannot cause any damage to the insteon devices themselves (donât really have the disposable capital to replace a broken PLM).
Config files are for wimps! The sendExtendedQuery() method is in the source code.
Nah, you shouldnât be able to trash the PLM. If buying a new PLM brings you in financial stress, be forewarned: they pretty reliably crap out after about 2-3 years.
Sorry to say, I have the whole house on Insteon + OpenHAB, but could not get it to work reliable enough for me to be happy with it, let alone my wife.
I have read about the issues with the PLM crapping out after two years. It was rather disappointing to hear but it is what it is. I am not too concerned about purchasing a PLM every couple years. I was more concerned about breaking a perfectly working device simply to gain an extra half a second.
I am also disappointed to hear that you could not get Insteon + OpenHAB to work reliably. Do you believe this is due to insteon or OpenHAB? Since I am at the beginning stages of my smart home development should I consider alternatives z-wave?
With that said, I am more than happy to test the modification if you can give me some instructions.
I didnât get around to it until today, but I was able to reduce the delay to about 1-2 sec by using Berndâs suggestion of eliminating the motion sensor battery/light reading and replacing it with m_feature.getDevice().doPoll(0);
I am working from the v1.8.3 release.
âSorry to say, I have the whole house on Insteon + OpenHAB, but could not get it to work reliable enough for me to be happy with it, let alone my wife.â
Based on your experience with the binding, where do you think the system is falling short? I ask because maybe myself, or someone else can take a look and attempt to improve things.
I had another house which had a lot of insteon devices, but I used ISY to control it. That worked great. However, in my current house I inherited Omnilink(power line), and thought I could add some insteon motion (because of RF) and then use Openhab to bridge the two technologies.
I have found the responsiveness of a motion sensor event to actually turning on the light to be too long to be useable(both insteon devices). Do you think it is feasible to make the messaging to the plm asynchronous? Or did you already try that and ran into issues?
Youâve clearly done a lot of work around this, and just hoping to glean some of your wisdom before I attempt to make any improvements and improve usability.
FYI, I wrote this post on June 11th, but somehow didnât hit the send button and just discovered my mistake today.
Great, so we potentially have a fix to these issues.
Please do me a favor and submit a pull request with your fix. I no longer understand how the whole build environment works, and what tree we should work off of (1.8.x vs 1.9), but I hope you can work it out.
My gripes were more with the openhab framework than with the binding. Problems with the binding I can fix, but not overall architectural decisions and some of the other components. I never got the âclassicâ GUI to work right, openhab takes minutes to start up, has huge memory consumption, I couldnât get a stack trace of a running system etc. Then the additional frustration that build procedures seem to have changed and I couldnât just straight forwardly follow the posted build instructions. To me breaking the tree is an absolute no-no. If the powers in charge donât value my time enough to keep the build environment in good shape I donât see a point of contributing.
Enough ranting. I suggest you first directly insteon-link the motion sensor to the light to see if that performance is good enough for you. You never want to use openhab for anything time critical (like switching lights on when you come into a rooom). Insteon is already pretty slow, openhab adds to it.
I too have had issues with the UI. However, I have found I can make a lot of home automation work with sensors(eg motion), or even Alexa as opposed to UI input. I find that the delay in grabbing your phone/tablet, then switching over to the app/safari is rather unacceptable. That part is my focus right now.
As you probably know, direct linking of the devices has limitations. For instance, I have a bathroom which is quite well lit during the day. I only want the motion sensor to turn on the lights for a period of the day based on sunset/sunrise(i.e. at night). This type of âsophisticationâ really relies on being able to run rules/programs. (I have found the light sensor in the motion detector to be not reliable enough)
I had all this running within an ISY at another house so I know it is possible. I am just trying to figure out if I should purchase another ISY for insteon devices here, or if Openhab can get responsive enough to avoid adding that hardware to the system.
The other wrinkle my current house contains both insteon and omnilink devices, so adding an ISY wonât be able to address all my needs either. I really do need something more generic such as openhab.
Unfortunately I am having doubts that I can control lights with motion sensors and such via openhab, as responsiveness is really important.
Iâve seen multiple reports of large latencies associated with rules defined using the openHAB Xtext DSL. I havenât had these issues when using Jython/JSR223 rules. My setup is smaller than Berndâs (about 400 items, numerous rules) but the performance and memory usage seems reasonable. I run on a RPi 3 along with several other servers (MQTT, etc.). I have three Insteon motion sensors that are controlling Hue and Insteon lights.
Iâve been able to get stack traces from running openHAB servers (using signals or triggering it from a rule based on specific conditions).
I share the frustrations with the build environments, especially now that weâre in limbo between openHAB 1 and 2.
