NEW 4 second delay between ELK and ISY processing??

[dbwarner5]

I have an Elk hardwired door sensor that triggers a garage light. Historically it would turn on fairly quickly ~ 1 to 1 ½ seconds from opening. 

Just recently that has changed to almost 4 seconds! Can anyone suggest a path forward to resolve this delay? 

Details> 

1) Wrote a simple program to test it. 

garage test - [ID 0207][Parent 00FB]

If
        Elk Zone 'Mud Room Door' is not Normal
 
Then
        Set 'Three Way Lighting / Garage Cans Three Way' Fast On
 
Else
        Set 'Three Way Lighting / Garage Cans Three Way' Fast Off
 

2) Have created two logs.. one on opening, one on closing. Both show a ~ 3 second delay from when the Elk registers the zone violation until the ISY does anything. See below. I have highlighted the two lights in the scene that gets activated. 

3) recent changes:

-upgraded to 5.16c

-polyisy with 9 different node servers, of which I stopped high traffic ones for the test

-rebooted Elk

-rebooted ISY

-no other hardware / connection changes

-ISY Inventory: 307 nodes, 516 programs, 98 scenes.

 

Any suggestions or help would be appreciated as 4 seconds is way too long to have a light come on.... thanks!

 

Isy Log Door Opened.pdf Isy Log Door Closed.pdf

[Bumbershoot]

3 minutes ago, dbwarner5 said:

Any suggestions or help would be appreciated as 4 seconds is way too long to have a light come on.... thanks!

 

I've experienced this, and for what it's worth, my issue turned out to be a networking problem, though I don't recall which device was the culprit.  The problem disappeared once I removed power from my Elk-M1XEP module for a few seconds, then reapplied power.  After the restart, it responded normally.  I did this well over a year ago, and it's been stable ever since.

[dbwarner5]

Hmm. I am pretty sure I rebooted that as well when inrebokts the elk 

 

what confuses me is thst the ISY sees the door violation but then does nothing for three seconds 

[Bumbershoot]

23 minutes ago, dbwarner5 said:

Hmm. I am pretty sure I rebooted that as well when inrebokts the elk 

 

what confuses me is thst the ISY sees the door violation but then does nothing for three seconds 

That's weird.  I just gave my setup a test, and looking at the Event Viewer, the reported times don't match either.  I open the door, and the light turns on immediately, even before I can get the door fully open.  The Event Viewer reports that the light turned on 3 seconds after the zone is violated.

I'm guessing that the logging is queued to make CPU time for events, so the logging times might not be completely accurate.

That doesn't help with your delay regarding the lights, however.  You might turn your Event Viewer to level 3 and see if you're beginning to see any communication issues to the switch.

[TrojanHorse]

What does the error log say?

[dbwarner5]

See my original post for the main log, at level 3.  Will look at the error  log and post it next. May have to re-run the test to get a clean shot

 

[dbwarner5]

Here is the error log for the time period of the two event logs I posted earlier. I dont really have any expertise in understanding what they are saying, so any help is appreciated. 

ISY Error Log.v5.0.16C__Tue 2020.03.17 01.51.21 PM.pdf

[simplextech]

How many Nodeservers are you running?  Which one's?

[dbwarner5]

Nine. but have two of the turned off temprarly to see if that was the cause as there was frequent traffic from them.

-Holiday Google - On

-Dark Sky -On

-Hue - On

-Kasa -On

-Timedata - OFF

-Holidays- On

-Sun - Off

-Isy Inventory - On

-Notificaion - On

[simplextech]

Not that many and not heavy traffic one's that are on.  I've seen where too much traffic can cause delay's.

[dbwarner5]

my thoughts too, so that is why I stopped the two as I noticed every minute and every ten seconds, there were updates happening. but that had no effect. 

Again, the Elk and Isy are talking immediately, but then. the log shows a 3 second delay for the isy to respond to it and then 1 second of processing at the Insteon level to get the light on. 

very strange. 

[TrojanHorse]

I’m following this as I had similar delays between Elk and ISY. Not consistently though. I’m still not convinced I have the problem solved. I’ll try to get more detail from the logs if it happens again.

I was initially thinking that some DHCP errors were causing my problem but I’m not sure.


Sent from my iPhone using Tapatalk

[Bumbershoot]

Here's a look at the Event Viewer on level 3 data when I do something similar.  I violated an Elk zone which runs a program to turn on the garage lights, among other things (I removed the variables that are set, extraneous devices values being set, the nodeserver data, etc., so there's more going on in the Event Viewer than this shows). 

The light was switched on immediately, before the door was fully opened (an Insteon On/Off relay switch).

I'm certainly no expert at interpreting these, but I think this line indicates that there was no issues with Insteon communications:

Tue 03/17/2020 15:23:41 : [Std-Direct Ack] 33.EB.01-->ISY/PLM Group=0, Max Hops=3, Hops Left=3

Tue 03/17/2020 15:23:41 : [ELK 0 193  0] Zone : Garage Door : Violated (51/2/0)
Tue 03/17/2020 15:23:41 : [INST-TX-I1  ] 02 62 33 EB 01 0F 11 FF
Tue 03/17/2020 15:23:41 : [INST-ACK    ] 02 62 33.EB.01 0F 11 FF 06          LTONRR (FF)
Tue 03/17/2020 15:23:41 : [INST-SRX    ] 02 50 33.EB.01 4A.A3.BA 2F 11 FF    LTONRR (FF)
Tue 03/17/2020 15:23:41 : [Std-Direct Ack] 33.EB.01-->ISY/PLM Group=0, Max Hops=3, Hops Left=3
Tue 03/17/2020 15:23:43 : [ELK 0 193  0] Zone : Garage Door : EOL (52/2/0)
Tue 03/17/2020 15:23:43 : [ELK 1   0  0] Area : Living Area : Not Ready To Arm (2/0/0)
Tue 03/17/2020 15:23:43 : [D2D EVENT   ] Event [33 EB 1 1] [ST] [255] uom=100 prec=0
Tue 03/17/2020 15:23:43 : [   33 EB 1 1]       ST 255 (uom=100 prec=0)
Tue 03/17/2020 15:23:43 : [D2D-CMP 0010] STS [33 EB 1 1] ST Converted values Event=255 Condition=255 prec=0
Tue 03/17/2020 15:23:43 : [D2D-CMP 0010] STS [33 EB 1 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=100 uom=51 prec=0) --> true

 

[Bumbershoot]

1 minute ago, TrojanHorse said:

I was initially thinking that some DHCP errors were causing my problem but I’m not sure.

That's what got me, I believe, when I experienced some slowness.

[dbwarner5]

hmm.. I may try to again reset things, but again, if you look at the first two lines of my event viewer, there is a 3 second delay before anything at all is registered, aligned with what I am experiencing with the lights. 

Tue 03/17/2020 09:59:54 AM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) 

Tue 03/17/2020 09:59:57 AM : [INST-TX-I1 ] 02 62 00 00 28 CF 12 00

[apostolakisl]

I'm not having any delays.  I open the door hard wired to Elk and ISY turns the light almost instantly.

[kclenden]

9 hours ago, dbwarner5 said:

1) Wrote a simple program to test it. 

garage test - [ID 0207][Parent 00FB]

I have a couple questions about the two logs you posted.  They each begin with a "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)" and then after two or three seconds are followed by a "[INST-TX-I1 ] 02 62 00 00 28 CF xx 00".  Did you delete anything between those lines or is there actually two to three seconds of complete lack of activity logged by the ISY"?

The test program you posted has an ID of 0207, but I don't see any indication in your two logs that it is ever activated.  I would expect to see something like "[D2D-CMP 0207]" to tell me that your test program was activated.  The "[INST-TX-I1 ] 02 62 00 00 28 CF xx 00" lines are Fast-On and Fast-Off commands being sent by the ISY to the PLM, so I'm assuming they are a result of the activation of your test program.  That would means there could be lines before the "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)" that might be useful to see what else is going on when your program is activated.  I haven't use Elk with my ISY so perhaps its events are logged differently and there isn't a corresponding [D2D] line.

[dbwarner5]

1 hour ago, kclenden said:

 

You said: They each begin with a "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)" and then after two or three seconds are followed by a "[INST-TX-I1 ] 02 62 00 00 28 CF xx 00".  Did you delete anything between those lines or is there actually two to three seconds of complete lack of activity logged by the ISY"?

--> No. that is the delay that I keep referencing.. what is going on? 

 You said: That would means there could be lines before the "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)"

--> I dont think there was anything. I cleared the log, so it was empty, while standing at the door, then immediately opened the door. The very first command is what appeared, if I remember correctly. I will try it again tomorrow and let you know. Its also interesting in that its a scene that is being turned on, but it sends out individual light commands, separated by quite a bit of activity, but I dont really have any understanding of the codes. 

 

Thanks!

[dbwarner5]

2 minutes ago, dbwarner5 said:

You said: They each begin with a "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)" and then after two or three seconds are followed by a "[INST-TX-I1 ] 02 62 00 00 28 CF xx 00".  Did you delete anything between those lines or is there actually two to three seconds of complete lack of activity logged by the ISY"?

--> No. that is the delay that I keep referencing.. what is going on? 

 You said: That would means there could be lines before the "[ELK 0 15 0] Zone : Mud Room Door : xxxxxxxx (51/x/0)"

--> I dont think there was anything. I cleared the log, so it was empty, while standing at the door, then immediately opened the door. The very first command is what appeared, if I remember correctly. I will try it again tomorrow and let you know. Its also interesting in that its a scene that is being turned on, but it sends out individual light commands, separated by quite a bit of activity, but I dont really have any understanding of the codes. 

 

Thanks!

In further thought about the second point. The elk command door open would be the first item.... its the elk telling the status change to the isy. the isy program then proves true and turns on the lights. I think most of that code is there, but it doesn't explain the 3 second gap between the first two events. That is what is concerning me the most as nothing that I can think of has changed.

[kclenden]

58 minutes ago, dbwarner5 said:

Its also interesting in that its a scene that is being turned on, but it sends out individual light commands,

In each case the ISY only sends out one command "02 62 00 00 28 CF 12 00" and "02 62 00 00 28 CF 14 00" respectively.  You can break those down to:

• "02 62" which is an ISY command to the PLM telling it to send the message that follows out over the power line
• "00 00 28" which is the address of the device the message is intended for, in this case it's a group number which all the devices in the scene will recognize
• "CF" which defines the type of message, in this case Group Broadcast, Standard Message, 3 message retransmissions remaining, 3 retransmissions allowed
• "12" and "14" which are the Fast On and Fast Off commands, respectively, that the ISY wants the devices to execute
• "00" which is not used by Category 2 devices.

Then in both cases you see "02 62 00.00.28 CF xx 00 06" which is a reply from the PLM that echos the original command and appends an "06" to indicate that it has received and sent out the command.  Everything after that is the result of devices having received the command.

[kclenden]

1 hour ago, dbwarner5 said:

I think most of that code is there, but it doesn't explain the 3 second gap between the first two events. That is what is concerning me the most as nothing that I can think of has changed.

Well, in the past @Michel Kohanim has said that the ISY tasks are broken up into different buckets based on type, and that the higher priority buckets are handled first.  I'll try to find one of those messages as it might shed some light on what other things you should check.

So I can see three possible causes for the delay:

• The ISY is handling other, higher priority, tasks
• For some reason the ISY has to wait on the PLM to become available before it can send out the Fast On or Fast Off commands
• The PLM has to wait for the powerline to settle down before it can send out the the ISY's message.  Though if this were the case, I would expect to see the delay show up between the "02 62 00.00.28 CF xx 00" and "02 62 00.00.28 CF xx 00 06" lines.

[kclenden]

Well that was easier than I expected:

 

 

[dbwarner5]

8 hours ago, kclenden said:

Well, in the past @Michel Kohanim has said that the ISY tasks are broken up into different buckets based on type, and that the higher priority buckets are handled first.  I'll try to find one of those messages as it might shed some light on what other things you should check.

So I can see three possible causes for the delay:

• The ISY is handling other, higher priority, tasks
• For some reason the ISY has to wait on the PLM to become available before it can send out the Fast On or Fast Off commands
• The PLM has to wait for the powerline to settle down before it can send out the the ISY's message.  Though if this were the case, I would expect to see the delay show up between the "02 62 00.00.28 CF xx 00" and "02 62 00.00.28 CF xx 00 06" lines.

I can understand that, but dont get it in relation to this situation as it is consistently a 4 second delay on this elk item, regardless of time of day or other activities which are always different. Also, I have other elk devices which dont seem to be having that delay, but I would need to do some specific tests to verify. Will do this as I verify the previous logs. 

Also will try to eliminate communication issues by shutting EVERYTHING down; cable modem, router, elk, elk accessories, isy and PLM, rebooting in the right order. 

Will report back later. 

Two other things that I also did recently; added one other program to. control those same lights-> will delete it for now, un-enrolled several Zwave devices and re-enrolled them as they were consistently acting up since my upgrade. This has solved the zwave issues. Will do a heal also just to be sure. 

If after this it is still acting this way, I will reach out to Michel and get his insights. 

Thanks.

[dbwarner5]

UPDATE: (See original post of this thread for background)

1) To ensure I am starting with a "clean" system, I unplugged and then rebooted the following, with delays and steady states in-between: Cable Modem, WifiRouter, IYS, PLM, ELK,  Elk accessories

2) test of door yielded a decrease of 1 second from 4 to 3 for the unknown delay between the event being recognized by ISY, and the next step. See attached Event viewer. 

3) On a second test of the above, an Elk wired motion detector is int he room and controls the lights (MD Mud Room). This communicates and isy responds immediately. No pause. See second attachment

4) However, on a wireless elk door sensor on a slider door, there was again a delay in the isy, from after receipt of the event change, to the very next line of anything happening. See third attachment. 

What is so strange is that this has just started happening fairly recently. I did a test on a different discussion with someone and this used to work physically in ~1.5 seconds. Now its close to 4. All the other physical times are also mimicking the delays in the isy.

Any ideas anyone? @Michel Kohanim  ? 

Door Open Log.pdf Elk other zone test 1.pdf Slider Test, Open and Close.pdf

[kclenden]

1 hour ago, dbwarner5 said:

4) However, on a wireless elk door sensor on a slider door, there was again a delay in the isy, from after receipt of the event change, to the very next line of anything happening.

All three of your tests show something different:

1. In the "Door Open Log", the ISY receives the ELK violation and then there is two seconds before it sends out a Fast On command to group 0x28.
2. In the "Elk other zone test 1", the ISY receives the ELK violation and immediately sends out an On command to group 0x23 and then immediately processes a [D2D EVENT] for devices 3C.D5.E5 but I don't see any communication to explain that event.
3. In the "Slider Test, Open and Close", the ISY receives the ELK violation and then immediately sends a Fast On command to device 45.8D.D3 and then immediately receives a response from device 45.8D.D3, but then waits 3 seconds before flagging a D2D Event for device 45.8D.D3.  Same thing happens on the close (Fast Off), but the delay between receiving a response from the device and  flagging a D2D event is only 2 seconds.

So the first thing we can say is that there is no consistency in your results.  The second is that they are all different tests:

• #1 and #3 both use a wireless device, but #1 sends a Fast On to a group, while #3 sends a Fast On to a device
• #2 uses a wired device and sends an On to a group

Some questions for each test:

1. What is device 3D.EC.D0?  What devices are in group 0x28?
2. What devices are in group 0x23?
3. What is device 45.8D.D3?  A response came back from 45.8D.D3 immediately which would say that it got the command and responded, so did it activate immediately?