dbwarner5 Posted March 20, 2020 Author Posted March 20, 2020 15 hours ago, kclenden said: CLARIFICATIONS IN BLUE 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. Yes that is correct. In my original post it was 3 seconds. Physically, it takes about another ~1 second on top of that to get the lights on, so the original total delay was ~4 seconds, now it's around 3 seconds. Just 2-4 weeks ago it was ~1.25 seconds, total. And again, how do you explain the "dead" time between the Elk violation and the Isy's first response? The Elk is responding almost immediately as witnessed by an ELK keypad next to the door. The ISY is getting the signal immediately, as witnessed by me watching the event log. Then the unknown delay, then things start happening again. This is a Wired door sensor. So First question: why they 2 (or previously 3) second delay? 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. This is also a Wired Elk device; motion detector. It is controlled by the following program that turns on a scene with three switches that are all controllers/responders in a scene that turns on the mud room overhead lights. One of the switch address is 3C D5 E5 1, another is 3D F7 DC 1 Mud Room Motion on - [ID 00FD][Parent 00F2] If Elk Zone 'MD Mud Room' is Violated And 'Mud from Garage' Status is Off And 'Mud from Kitchen' Status is Off And 'Mud from Hall' Status is Off Then Set 'Three Way Lighting / Mud room Three Way' On Else Wait 3 minutes Set 'Three Way Lighting / Mud room Three Way' Off So this raises the second question; why does one wired sensor have a 2 second delay for the ISY, while the other does not? I also do not know why there is no communication to explain that event per your question. 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. Yes. device 45.8D.D3 is the light that I temporarily had the following program turning on from this Wireless Elk door sensor. TEst slider - [ID 0209][Parent 0147] If Elk Zone 'Sliding Door' is Violated Then Set 'K Island Cans' Fast On Else Set 'K Island Cans' Fast Off 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: Yes and No: #1 and #3 both use a wireless device, .... #2 uses a wired device..... The first two tests are both wired elk sensors; one a door button, the other a Honeywell PIR. The third test is different; an Elk Wireless Door sensor. .....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 The first test was FAST ON to a scene/group, the second test is an ON to a scene/group, and last test uses a FAST ON to a single device. But again, there is this unknown delay happening between ISY reciept of the elk condition and the ISY beginning to process, which should be independent of these differences in the programs. However, if it would help, I can make tests programs that are all FAST ONs to a single device, or a group, or regular ON's to a single device or group and redo all three? Some questions for each test: What is device 3D.EC.D0? What devices are in group 0x28? Devices in Group: 3D.EC.D0 and 28.B6.57. Both of these show up in the first log as D2D events. What devices are in group 0x23? Devices in Group: 3D.F7.DC, 3C.D5.E5 and 3D.14.1B. The first two show up in the logs as D2D events. I cut the log short when I pasted it. All three show up in the original version (not attached) 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? This is the light that I have in the program below. And yes it turned on immediately.i just retested and same result. Immediate. ** HOWEVER.... I just changed it to a scene and I am back to a 3 second delay !!!! @kclenden Thanks for your questions. I hope I have clarified my situation. Immediately, based on the last quick test, it appears that the differentiating factor is a scene vs an individual light. I will do some more tests on that and see what I come up with. THANKS!
dbwarner5 Posted March 20, 2020 Author Posted March 20, 2020 Ok, so I did some further testing of scene vs single switch, vs program vs fast on/off an regular on/of and got the following conclusions: -Simple Program, single light --> Immediate -Simple Program, Scene --> 3 second delay -Original (more complex) program, single light --> 3 second delay -Original (more complex)program, Scene --> 3 second delay. Here is all the event logs and the two (base) programs I used. 1) Simple Mud Room Door open program with a FASTON to ONE light switch (vs scene in previous post). Immediate results: Fri 03/20/2020 01:04:39 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Fri 03/20/2020 01:04:40 PM : [INST-TX-I1 ] 02 62 3D EC D0 0F 12 00 --> This is the single light being turned on. Fri 03/20/2020 01:04:40 PM : [INST-ACK ] 02 62 3D.EC.D0 0F 12 00 06 LTON-F (00) Fri 03/20/2020 01:04:40 PM : [INST-SRX ] 02 50 3D.EC.D0 46.C2.4C 2F 12 00 LTON-F (00) Fri 03/20/2020 01:04:40 PM : [Std-Direct Ack] 3D.EC.D0-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Fri 03/20/2020 01:04:42 PM : [D2D EVENT ] Event [3D EC D0 1] [ST] [255] uom=100 prec=0 I repeated the test with a regular On, as well as closing / off. All four tests yielded the same result --> immediate light change. 2) Went back to the original program and changed the scene to one of the two switches in the three-way with load. Result was again a 3 second unknown delay in the ISY!! Fri 03/20/2020 01:14:16 PM : [ELK 0 22 0] Zone : MD Mud Room : Violated (51/2/0) Fri 03/20/2020 01:14:16 PM : [ELK 0 22 0] Zone : MD Mud Room : Open (52/1/0) Fri 03/20/2020 01:14:18 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Fri 03/20/2020 01:14:21 PM : [INST-TX-I1 ] 02 62 3D EC D0 0F 12 00 --> This is the single light being turned on. NOTICE THE DELAY OF 3 SECONDS HERE Fri 03/20/2020 01:14:21 PM : [INST-ACK ] 02 62 3D.EC.D0 0F 12 00 06 LTON-F (00) Fri 03/20/2020 01:14:21 PM : [ELK 0 15 0] Zone : Mud Room Door : Open (52/1/0) Fri 03/20/2020 01:14:21 PM : [ELK 1 0 0] Area : Main House : Ready To Arm w/ Zone Violated (2/2/0) Fri 03/20/2020 01:14:21 PM : [ELK 0 0 1] Keypad : Mud Room : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:14:21 PM : [INST-SRX ] 02 50 3D.EC.D0 46.C2.4C 2F 12 00 LTON-F (00) Fri 03/20/2020 01:14:21 PM : [Std-Direct Ack] 3D.EC.D0-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Fri 03/20/2020 01:14:21 PM : [ELK 0 0 1] Keypad : Mud Room : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:14:21 PM : [ELK 0 0 2] Keypad : Master Bedroom : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:14:21 PM : [ELK 0 0 2] Keypad : Master Bedroom : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:14:21 PM : [ELK 0 0 3] Keypad : Sun Room : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:14:21 PM : [ELK 0 0 3] Keypad : Sun Room : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:14:21 PM : [ELK 0 22 0] Zone : MD Mud Room : Normal (51/0/0) Fri 03/20/2020 01:14:21 PM : [ELK 0 22 0] Zone : MD Mud Room : Short (52/3/0) Fri 03/20/2020 01:14:21 PM : [D2D EVENT ] Event [3D EC D0 1] [ST] [255] uom=100 prec=0 3) Went back to the simple program and changed the single light to the three-way scene. Again, a 3 second delay! Fri 03/20/2020 01:54:41 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Fri 03/20/2020 01:54:44 PM : [INST-TX-I1 ] 02 62 00 00 28 CF 11 00 --> 3 second unknown delay Fri 03/20/2020 01:54:44 PM : [INST-ACK ] 02 62 00.00.28 CF 11 00 06 LTONRR (00) Fri 03/20/2020 01:54:44 PM : [ELK 0 15 0] Zone : Mud Room Door : Open (52/1/0) Fri 03/20/2020 01:54:44 PM : [ELK 1 0 0] Area : Main House : Ready To Arm w/ Zone Violated (2/2/0) Fri 03/20/2020 01:54:44 PM : [ELK 0 22 0] Zone : MD Mud Room : Violated (51/2/0) Fri 03/20/2020 01:54:44 PM : [ELK 0 22 0] Zone : MD Mud Room : Open (52/1/0) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 1] Keypad : Mud Room : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 1] Keypad : Mud Room : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 2] Keypad : Master Bedroom : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 2] Keypad : Master Bedroom : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 3] Keypad : Sun Room : F3 = Arm Away LED Off (112/0/3) Fri 03/20/2020 01:54:44 PM : [ELK 0 0 3] Keypad : Sun Room : F4 = Arm Stay LED Off (112/0/4) Fri 03/20/2020 01:54:44 PM : [D2D EVENT ] Event [3D EC D0 1] [ST] [255] uom=100 prec=0 Here are the two (base) programs: Simple: garage test - [ID 0207][Parent 00FB] If Elk Zone 'Mud Room Door' is Violated Then Set 'Garage Cans at Mud room' Fast On Else Set 'Garage Cans at Mud room' Fast Off Original : Garage On - [ID 00FE][Parent 00FB] If ( Elk Zone 'MD Garage North' is Violated Or Elk Zone 'MD Garage Mid' is Violated Or Elk Zone 'MD Garage South' is Violated ) Or ( Elk Zone 'MD Mud Room' is Violated And ( Elk Zone 'Mud Room Door' is Violated Or Elk Zone 'Mud Room Door' is Bypassed ) ) Then Set 'Garage Cans at Mud room' Fast On Else Wait 5 minutes Set 'Garage Cans at Mud room' Off Set 'Garage Cans at Service door' Off Set 'Garage Workbench by workbnch' Off Set 'Garage Workbench by Overhead' Off Set 'Garage Sink' Off So there are two things that are affecting the speed of reaction: Scene vs single switch, and the program as follows: This is so odd... help? I am going to delete the original complex program and re-write it. Just to repeat myself, nothing changed to this program prior to this delay being noticed. So what is going on here? Thanks
Michel Kohanim Posted March 20, 2020 Posted March 20, 2020 @dbwarner5, Before you go deep into this analysis, the first thing I would do is to use Run Then (instead of sending events). If Run Then also exhibits the same delays, then the issue is signal/noise on INSTEON side. If Run Then does NOT exhibit the same delay, then the issue is ISY processing of the events ... maybe it's just too busy. With kind regards, Michel
dbwarner5 Posted March 20, 2020 Author Posted March 20, 2020 @Michel Kohanim Running then is INSTANT. so no delays there. The isy being busy is a possibility, but nothing is showing on the logs, and its strange that its only this area, at all times of the day, with the delay.
dbwarner5 Posted March 20, 2020 Author Posted March 20, 2020 @Michel Kohanim Running Then is instantaneous in all cases: both programs, scenes or individual switches.. Letting the program run by itself: 3 second delays in all cases except the simple program and one switch. consistent. something is wrong. Just re-wrote the original program with single switch and it runs as expected.... change to a scene, and delay is there again
kclenden Posted March 21, 2020 Posted March 21, 2020 6 hours ago, dbwarner5 said: something is wrong. I don't know enough about the internal coding of the ISY to really say what might be going on. From the outside all we can do is observe how it reacts. Here are two programs that might give you a little more insight about where the delay is manifesting, or maybe just some information about where it isn't manifesting. KeepTime - [ID 00B8][Parent 0001] If - No Conditions - (To add one, press 'Schedule' or 'Condition') Then // We'll only execute 120 times so that the program will stop after 2 minutes // just in case we forget to stop it Repeat 120 times // Use Wait 0 seconds. For some reason, Wait 1 seconds results in the Event Log updating every // 2 seconds, while Wait 0 seconds results in the Event Log updating every second. Wait 0 seconds $sTest = 0 $sTest = 1 Else - No Actions - (To add one, press 'Action') CheckTime - [ID 00B9][Parent 0001] If $sTest is 1 Then $sTest = 2 $sTest = 3 Else - No Actions - (To add one, press 'Action') Both programs require you to create a state variable called "sTest". The first program will run for two minutes and put two lines into the Event Viewer log every second. You should run its THEN right before you try one of the tests that gives you a 3 second delay. If those lines continue to appear during the 3 second delay it tells you that the ISY is still running programs. The second program reacts to the first program and also will put two lines into the Event Viewer log every second. If those lines continue to appear during the 3 second delay it tells you that the ISY is still evaluating IFs. The results from the two programs above may only satisfy our curiosity, but perhaps it will help UDI track down what might be happening.
Teken Posted March 22, 2020 Posted March 22, 2020 If you have a lot of Network Resources (NR) and email sends this too can impact the responsiveness of the controller. Disable them all and see what happens with the response time. Also perform a scene test and let us know if you still observe the 4 second delay while enabling / disabling the above two items. Lastly, anything that sends network traffic to the controller will surely impact its responsiveness which also leads to any REST subscriptions. If you also have any Insteon battery devices which have pending writes this will slow down the controller so get them updated. Programs which flicker quickly (folder status) indicates massive activity in that program(s). Good luck Sent from my iPhone using Tapatalk
Michel Kohanim Posted March 22, 2020 Posted March 22, 2020 @dbwarner5, You should change the Event Viewer level to 3, and redo your experiments. This time check the error log. Please note that the more events are in the queue, the longer it takes to process a program for them . With kind regards, Michel
dbwarner5 Posted March 22, 2020 Author Posted March 22, 2020 These have all been good suggestions. After more testing, below are my conclusions. All logs are at level 3. -Very consistently, I can duplicate the results by changing the target in the THEN statement between a DEVICE and a SCENE -According to @kclenden programs above, you will see that NOTHING happens during the delay of the ISY. This has been consistent since my first posting. -However once it starts to process it does a lot of work very quickly. See last test below. So @Michel Kohanim, if we can’t get any better ideas here, I will start a ticket, as this behavior is worrisome. Thanks. Here are the latest test results (short snippets). All physical results mimic times delays shown. PROGRAM CALLS A DEVICE WITHOUT TEST PROGRAMS: NO DELAY Event Viewer: Sun 03/22/2020 04:49:56 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Sun 03/22/2020 04:49:56 PM : [INST-TX-I1 ] 02 62 3D EC D0 0F 12 00 Error Log: No errors around that time. Sun 2020/03/22 04:49:50 PM System -170001 [HTTP:0-20]: GET-->/rest/ns/8/nodes/n008_contro Sun 2020/03/22 04:49:50 PM System -170001 [HTTP:0-20] Closing socket normally Sun 2020/03/22 04:49:59 PM System -170001 [HTTP:0-30-5] 10.0.1.166:56621->92 Sun 2020/03/22 04:49:59 PM System -170001 [HTTP:0-30]: POST[1]-->/services Sun 2020/03/22 04:49:59 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus xmlns:u= Sun 2020/03/22 04:49:59 PM System -170001 [HTTP:0-30-5] 10.0.1.166:56625->92 Sun 2020/03/22 04:49:59 PM System -170001 [HTTP:0-30]: POST[1]-->/services Sun 2020/03/22 04:49:59 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus PROGRAM CALLS A SCENE WITHOUT TEST PROGRAMS: 3 SECOND DELAY Event Viewer: Sun 03/22/2020 04:52:03 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Sun 03/22/2020 04:52:06 PM : [INST-TX-I1 ] 02 62 00 00 28 CF 11 00 Error log: Sun 2020/03/22 04:52:06 PM System -170001 [HTTP:0-20-5] 10.0.1.23:52375->92 Sun 2020/03/22 04:52:06 PM System -170001 [HTTP:1-19-5] 10.0.1.23:26403->92 Sun 2020/03/22 04:52:06 PM System -170001 [HTTP:1-19]: GET-->/rest/ns/5/nodes/n005_timeda Sun 2020/03/22 04:52:07 PM System -170001 [HTTP:0-20]: GET-->/rest/ns/5/nodes/n005_timeda Sun 2020/03/22 04:52:07 PM System -170001 [HTTP:1-19] Closing socket normally Sun 2020/03/22 04:52:08 PM System -170001 [HTTP:0-20] Closing socket normally The following are the same two test above, but with the two test programs from @kclendon running as well. PROGRAM CALLS A DEVICE WITH TEST PROGS RUNNING: NO DELAY Event Viewer: Sun 03/22/2020 05:06:11 PM : [VAR 2 52 ] 0 Sun 03/22/2020 05:06:11 PM : [VAR 2 52 ] 1 Sun 03/22/2020 05:06:11 PM : [VAR 2 52 ] 2 Sun 03/22/2020 05:06:11 PM : [VAR 2 52 ] 3 Sun 03/22/2020 05:06:12 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Sun 03/22/2020 05:06:12 PM : [INST-TX-I1 ] 02 62 3D EC D0 0F 12 00 Sun 03/22/2020 05:06:12 PM : [INST-ACK ] 02 62 3D.EC.D0 0F 12 00 06 LTON-F (00) Sun 03/22/2020 05:06:12 PM : [INST-SRX ] 02 50 3D.EC.D0 46.C2.4C 2F 12 00 LTON-F (00) Sun 03/22/2020 05:06:12 PM : [Std-Direct Ack] 3D.EC.D0-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/22/2020 05:06:16 PM : [VAR 2 52 ] 0 Sun 03/22/2020 05:06:16 PM : [INST-TX-I1 ] 02 62 28 B6 57 0F 12 00 Sun 03/22/2020 05:06:16 PM : [INST-ACK ] 02 62 28.B6.57 0F 12 00 06 LTON-F (00) Sun 03/22/2020 05:06:16 PM : [VAR 2 52 ] 1 Error Log: no relevant activity during program Sun 2020/03/22 05:06:11 PM System -170001 [HTTP:0-19]: POST[1]-->/services Sun 2020/03/22 05:06:11 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus xmlns:u= Sun 2020/03/22 05:06:19 PM System -170001 [HTTP:0-28-5] 10.0.1.166:58428->92 Sun 2020/03/22 05:06:19 PM System -170001 [HTTP:0-28]: POST[1]-->/services Sun 2020/03/22 05:06:19 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus xmlns:u= Sun 2020/03/22 05:06:20 PM System -170001 [HTTP:0-28-5] 10.0.1.166:58429->92 PROGRAM CALLS A SCENE WITH TEST PROGS RUNNING: 4 SECOND DELAY Event Viewer: Sun 03/22/2020 05:02:11 PM : [VAR 2 52 ] 0 Sun 03/22/2020 05:02:11 PM : [VAR 2 52 ] 1 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 2 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 3 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 0 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 1 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 2 Sun 03/22/2020 05:02:12 PM : [VAR 2 52 ] 3 Sun 03/22/2020 05:02:12 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Sun 03/22/2020 05:02:16 PM : [INST-TX-I1 ] 02 62 00 00 28 CF 11 00 Sun 03/22/2020 05:02:16 PM : [ELK 0 15 0] Zone : Mud Room Door : Open (52/1/0) Sun 03/22/2020 05:02:16 PM : [INST-ACK ] 02 62 00.00.28 CF 11 00 06 LTONRR (00) Sun 03/22/2020 05:02:16 PM : [ELK 1 0 0] Area : Main House : Ready To Arm w/ Zone Violated (2/2/0) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 1] Keypad : Mud Room : F3 = Arm Away LED Off (112/0/3) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 1] Keypad : Mud Room : F4 = Arm Stay LED Off (112/0/4) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 2] Keypad : Master Bedroom : F3 = Arm Away LED Off (112/0/3) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 2] Keypad : Master Bedroom : F4 = Arm Stay LED Off (112/0/4) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 3] Keypad : Sun Room : F3 = Arm Away LED Off (112/0/3) Sun 03/22/2020 05:02:16 PM : [ELK 0 0 3] Keypad : Sun Room : F4 = Arm Stay LED Off (112/0/4) Sun 03/22/2020 05:02:16 PM : [D2D EVENT ] Event [3D EC D0 1] [ST] [255] uom=100 prec=0 Sun 03/22/2020 05:02:16 PM : [ 3D EC D0 1] ST 255 (uom=100 prec=0) Sun 03/22/2020 05:02:16 PM : [D2D-CMP 01DF] STS [3D EC D0 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 01DF] STS [3D EC D0 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 017B] STS [3D EC D0 1] ST Converted values Event=255 Condition=255 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 017B] STS [3D EC D0 1] ST op=6 Event(val=255 uom=100 prec=0) != Condition(val=100 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00FA] STS [3D EC D0 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00FA] STS [3D EC D0 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00DE] STS [3D EC D0 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00DE] STS [3D EC D0 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AD] STS [3D EC D0 1] ST Converted values Event=255 Condition=255 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AD] STS [3D EC D0 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=100 uom=51 prec=0) --> true Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AC] STS [3D EC D0 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AC] STS [3D EC D0 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D EVENT ] Event [28 B6 57 1] [ST] [255] uom=100 prec=0 Sun 03/22/2020 05:02:16 PM : [ 28 B6 57 1] ST 255 (uom=100 prec=0) Sun 03/22/2020 05:02:16 PM : [D2D-CMP 01DF] STS [28 B6 57 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 01DF] STS [28 B6 57 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 017B] STS [28 B6 57 1] ST Converted values Event=255 Condition=255 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 017B] STS [28 B6 57 1] ST op=6 Event(val=255 uom=100 prec=0) != Condition(val=100 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00DE] STS [28 B6 57 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00DE] STS [28 B6 57 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AD] STS [28 B6 57 1] ST Converted values Event=255 Condition=255 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AD] STS [28 B6 57 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=100 uom=51 prec=0) --> true Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AC] STS [28 B6 57 1] ST Converted values Event=255 Condition=0 prec=0 Sun 03/22/2020 05:02:16 PM : [D2D-CMP 00AC] STS [28 B6 57 1] ST op=1 Event(val=255 uom=100 prec=0) is Condition(val=0 uom=51 prec=0) --> false Sun 03/22/2020 05:02:17 PM : [VAR 2 52 ] 0 Sun 03/22/2020 05:02:17 PM : [VAR 2 52 ] 1 Sun 03/22/2020 05:02:17 PM : [VAR 2 52 ] 0 Error Log; No Activity around program run time. Sun 2020/03/22 05:02:13 PM System -170001 [HTTP:0-28-5] 10.0.1.166:57918->92 Sun 2020/03/22 05:02:13 PM System -170001 [HTTP:0-28]: POST[1]-->/services Sun 2020/03/22 05:02:13 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus xmlns:u= Sun 2020/03/22 05:02:19 PM System -170001 [HTTP:0-19-5] 10.0.1.166:57926->92 Sun 2020/03/22 05:02:19 PM System -170001 [HTTP:0-19]: POST[1]-->/services Sun 2020/03/22 05:02:19 PM System -170001 <s:Envelope><s:Body><u:GetSystemStatus
dbwarner5 Posted March 22, 2020 Author Posted March 22, 2020 FOLLOW UP to above post: Two additional observations of the data: In test three, PROGRAM CALLS A DEVICE WITH TEST PROGS RUNNING: NO DELAY. A strange four second delay occurs later: Sun 03/22/2020 05:06:12 PM : [Std-Direct Ack] 3D.EC.D0-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/22/2020 05:06:16 PM : [VAR 2 52 ] 0 2. In the delay in test four, PROGRAM CALLS A SCENE WITH TEST PROGS RUNNING: 4 SECOND DELAY, the delay occurs at the same seconds (different minutes) of the hour. from x:12 until x:16. Strange coincidence?
kclenden Posted March 23, 2020 Posted March 23, 2020 2 hours ago, dbwarner5 said: Strange coincidence? I'm going to guess that it's just a strange coincidence since the other test logs you've posted have shown delays at different seconds. In your two most recent tests above, the thing that sticks at me is that in the "device" test there is only one Elk notification (the original violation) while in the "scene" test there are many Elk notifications. What causes those extra notifications during the scene test? Perhaps what's happening is that the ISY is stuck processing all those notifications coming in via the network before it releases the processor to work on all other buckets of tasks. Then it dumps everything to the Event Viewer and they all show up in the same "second". A couple more things you might try to narrow down the culprit: Put a "$sTest = 4" right before your commands to turn On or Off a scene or device and put a "$sTest = 5" after the command. That might tell us whether the delay is kicked off by the actual command to control a device or scene versus the original Elk violation. Change the If condition so that your programs are triggered by an Insteon device instead of the Elk. If the delay goes away it would seem to point the finger at the interaction between the Elk and the ISY.
dbwarner5 Posted March 23, 2020 Author Posted March 23, 2020 Ok.. good next steps. So far, I can duplicate this delay when there is an Elk Violation in the IF, followed by a scene trigger in the THEN. This combination is driving a delay. I have created this scenerio in three separate programs, albeit the same elk violation and the same scene. Will post var 4 and 5 tests later. Will also try a few other combinations to see if I can duplicate these results as the above issue. -same program, other scenes, -same program, change to an Insteon trigger, same scene and lastly, a completely different program / trigger / scene vs device. Thanks
Michel Kohanim Posted March 23, 2020 Posted March 23, 2020 @dbwarner5, In Configuration | System tab, there's a setting under System: Wait while busy reading. This applies only to scenes because of many bugs with INSTEON scene cleanup. You can uncheck at your own peril. With kind regards, Michel
dbwarner5 Posted March 23, 2020 Author Posted March 23, 2020 1 hour ago, Michel Kohanim said: . You can uncheck at your own peril. that sounds ominous.... I just finished 14 different tests. Will post the results. But it seems that there is a consistent and repeatable 3-4 second issue driven by: Elk Trigger followed by a SCENE event in the THEN. Maybe someone else can attempt to repeat it? This is all relatively new, so something has changed.
dbwarner5 Posted March 23, 2020 Author Posted March 23, 2020 So based on @kclenden suggestion, I ran most of the various permutations of Program, Trigger, and Scene vs Device. CONSISTENTLY, an ELK trigger when followed by a SCENE, sees the ISY going into a NO ACTION mode and then after delay, it continues to process per the logs. All tests have Kclendon’s test variable programs running; Var=0,1 running a repeat, Var=2, 3 running an IF, Var=4 first line of test program, Var=5 last line of test program All physical delays matched ISY delays. One strange anomaly was in test 2 and test 12, there was a considerable delay the first time it ran. Afterwards, it there was no delay TEST RESULTS: Test 1: Orig Program with orig Elk trigger and orig Scene —> 3-4 second delays Test 2: Orig Program with orig Elk trigger and orig Device —> First run delay, second and subsequent runs No delay Test 3: Orig Program with orig Elk Trigger and new Scene —> 3-4 second delay Test 4: Orig Progrma with orig Elk Trigger and new Device —> No delay Test 5: Orig Program with Insteon trigger and orig Scene —> very slight delay Test 6: Orig Program with Insteon trigger and orig Device —> very slight delay Test 7: Orig Program with Insteon trigger and new Scene —> very slight delay Test 8: Orig Program with Insteon trigger and new Device —> very slight delay Test 9: New Program with orig Elk Trigger and new Scene —> Long delay Test 10: New Program with orig Elk Trigger and new Device—> No delay (no need to do new program with orig elk and orig scene as I have done this three times with same result) Test 11: New Program with new Elk Trigger and orig Scene —> Long delay Test 12: New Program with new Elk Trigger and orig Device —> First run delay, second and subsequent runs No delay Test 13: New Program with new Elk Trigger and new Scene —> Long delay Test 14: New Program with new Elk Trigger and new Device —> No Delay Snippets of selected logs. No lines were deleted in the flows. Test 1: Mon 03/23/2020 12:17:52 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Mon 03/23/2020 12:17:56 PM : [VAR 2 52 ] 0 *** 4 SECONDS OF NO ACTIVITY Mon 03/23/2020 12:17:56 PM : [VAR 2 52 ] 1 Mon 03/23/2020 12:17:56 PM : [ELK 0 15 0] Zone : Mud Room Door : Open (52/1/0) Mon 03/23/2020 12:17:56 PM : [D2D EVENT ] Event [n008_controller] [DON] [0] uom=0 prec=-1 Mon 03/23/2020 12:17:56 PM : [n008_controller] DON 0 Mon 03/23/2020 12:17:56 PM : [VAR 2 52 ] 4 *** PROGRAM BEGINS HERE AND ENDS TWO LINES LATER Mon 03/23/2020 12:17:56 PM : [INST-TX-I1 ] 02 62 00 00 28 CF 11 00 Mon 03/23/2020 12:17:56 PM : [VAR 2 52 ] 5 *** PROGRAM ENDS HERE Test 3: Mon 03/23/2020 12:20:15 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Mon 03/23/2020 12:20:18 PM : [VAR 2 52 ] 0. *** 3 SECONDS OF NO ACTIVITY Mon 03/23/2020 12:20:18 PM : [VAR 2 52 ] 1 Mon 03/23/2020 12:20:18 PM : [ELK 0 15 0] Zone : Mud Room Door : Open (52/1/0) Mon 03/23/2020 12:20:18 PM : [VAR 2 52 ] 4 *** PROGRAM BEGINS HERE AND ENDS TWO LINES LATER Mon 03/23/2020 12:20:18 PM : [INST-TX-I1 ] 02 62 00 00 6D CF 11 00 Mon 03/23/2020 12:20:18 PM : [VAR 2 52 ] 5 *** PROGRAM ENDS HERE Test 9: Mon 03/23/2020 12:40:17 PM : [VAR 2 52 ] 0 Mon 03/23/2020 12:40:17 PM : [VAR 2 52 ] 1 Mon 03/23/2020 12:40:17 PM : [VAR 2 52 ] 2 Mon 03/23/2020 12:40:17 PM : [VAR 2 52 ] 3 Mon 03/23/2020 12:40:17 PM : [ELK 0 15 0] Zone : Mud Room Door : Violated (51/2/0) Mon 03/23/2020 12:40:27 PM : [VAR 2 52 ] 4 *** PROGRAM BEGINS HERE AND ENDS THREE LINES LATER Mon 03/23/2020 12:40:27 PM : [INST-TX-I1 ] 02 62 00 00 55 CF 12 00 Mon 03/23/2020 12:40:27 PM : [INST-ACK ] 02 62 00.00.55 CF 12 00 06 LTON-F (00) Mon 03/23/2020 12:40:27 PM : [VAR 2 52 ] 5 *** PROGRAM ENDS HERE Test 13: Mon 03/23/2020 12:55:55 PM : [VAR 2 52 ] 2 Mon 03/23/2020 12:55:55 PM : [VAR 2 52 ] 3 Mon 03/23/2020 12:55:55 PM : [ELK 0 33 0] Zone : Sliding Door : Violated (51/2/0) Mon 03/23/2020 12:56:04 PM : [VAR 2 52 ] 4 *** PROGRAM BEGINS HERE AND ENDS THREE LINES LATER Mon 03/23/2020 12:56:04 PM : [INST-TX-I1 ] 02 62 00 00 66 CF 12 00 Mon 03/23/2020 12:56:04 PM : [INST-ACK ] 02 62 00.00.66 CF 12 00 06 LTON-F (00) Mon 03/23/2020 12:56:04 PM : [VAR 2 52 ] 5 *** PROGRAM ENDS HERE
kclenden Posted March 24, 2020 Posted March 24, 2020 6 hours ago, dbwarner5 said: Test 9: New Program with orig Elk Trigger and new Scene —> Long delay 6 hours ago, dbwarner5 said: Test 13: New Program with new Elk Trigger and new Scene —> Long delay Wow! You're not kidding about the long delays. One is 10 seconds and the other is 9 seconds. How full is your PLM Links table? I ask because in theory new scenes would appear at the end of the table and perhaps where the scene is represented in the PLM Links table is having an impact (even though as far as I know it shouldn't). If you do Tools->Diagnostics->Show PLM Links Table, followed by clicking "Start" you can see the table.
dbwarner5 Posted March 24, 2020 Author Posted March 24, 2020 yikes.. 949 links.. I think a year or so ago, I was having strange behavior and eventually after new PLM etc, Michel gave me the hint that I might have to many links.. I think this is around that number again. Its a real pain in the A_ _ limitation, as I have to eliminate scene and recreate them as programs. That may be the next step... is there a way to test this by doing a back up, and then deleting a large number of scenes.. reboot etc, then rerun the test? Either way, I could then do a restore of the backup and then selectively fix the problem if it proved out? Risks? and thoughts ? Thanks.
kclenden Posted March 25, 2020 Posted March 25, 2020 20 hours ago, dbwarner5 said: That may be the next step... is there a way to test this by doing a back up, and then deleting a large number of scenes.. reboot etc, then rerun the test? When you backup the ISY, you're also backing up its copies of the PLM and Device Links tables. The issue is that when you restore an ISY from backup, it doesn't automatically update the actual PLM and Device Links tables. To do that you have to manually execute a "Restore Devices" command. And that can take a long time depending on how many devices you have and how easily communication is on your powerline. Here's the link to the Wiki that talks about restoring the ISY: https://wiki.universal-devices.com/index.php?title=ISY-99i/ISY-26_INSTEON:File_Menu#Restore_ISY Before you do any of that, would you be willing to share your PLM Links table? I'm curious whether all those links are actually active or if some of them are deleted links just taking up space as well as if there are any corrupted records. Just so you know, the PLM Links Table includes the Device Address, Category, Subcategory and Version for all of your devices. I'm sure that information could be useful to hackers, so I certainly won't be offended if you don't want to share it. If you are willing, just save the Show PLM Links Table results to an XML file and then you could share it with me via a PM. If there are a lot of deleted records just taking up space, it's possible that they would be cleared out if you simply did a "Restore Devices" command. That depends on how UD implemented the restore process. I can't think of a reason why they would restore deleted records, but maybe there's a valid reason. Perhaps @Michel Kohanim can tell us whether the ISY cleans up deleted records as it goes, or if they can accumulate and then if they can accumulate whether a "Restore Devices" command would effectively clear them out of the PLM Links Table.
dbwarner5 Posted March 25, 2020 Author Posted March 25, 2020 I did some digging on older posts with similar possible PLM limit issues and a Restore PLM activity looks to be effective in cleaning up old / duplicate links. However it requires access to your battery driven, which is frankly a PITA. Additionally, the most recent model before the current model is said to act up at ~950-1000 links, with the newest model at ~2000. I am pretty sure I have the pervious version. Lastly. activity will affect the links table count. just to be sure, I did it twice and both times got 950 (not 949). I will run it now and send it to. you for your thoughts.
Brian H Posted March 25, 2020 Posted March 25, 2020 Where did you see 2000? The presently sold 2413S PLM is specified as a +1000 link database. The sales page on Smarthome had what looked like an error on it awhile back, indicating 2000. The sales page now says +1000 links not 2000. The early revision 2412S power line only PLM was 417 link database and the later revisions 2016 link database. It had a slower clock speed than the 2413S and most found more than ~800 links would miss things. The new 2234-223 (RS232) serial port version. PLM that is in the FCC Database has ~4000 link. We have no idea when or if it will see the light of day. The Smartenit EZIComm PLM. Is built on the 2412 base board made for them by Smarthome and may still have a 2000 link database. It would probably have the same slower clock and more than ~800 links would miss things.
dbwarner5 Posted April 10, 2020 Author Posted April 10, 2020 On 3/25/2020 at 6:53 AM, Brian H said: Where did you see 2000? sorry, cant remember.. just perusing different forum posts.. got my links down to about 500 or so and it seems to be working more predictably. Seems kinda ridiculous that there is a limit of such as "Scenes" are one of the major features of an Insteon set up. But with smart home, am not surprised. Thanks.
TrojanHorse Posted April 11, 2020 Posted April 11, 2020 sorry, cant remember.. just perusing different forum posts.. got my links down to about 500 or so and it seems to be working more predictably. Seems kinda ridiculous that there is a limit of such as "Scenes" are one of the major features of an Insteon set up. But with smart home, am not surprised. Thanks. My understanding is that the 2000 links is an expected new product release. Maybe based on some FCC filings? Can’t / didn’t care to really remember. Let’s hope we see it someday. Sent from my iPhone using Tapatalk
Brian H Posted April 11, 2020 Posted April 11, 2020 The new one 22342 in the FCC Database is 4000 links. Universal AC power. Serial port version can again supply 5VDC to things like the ISY994i. Faster internal clock speed. For awhile Smarthome was listing the 2413S PLM having a 2000 link database. It quietly disappeared going back to the 1000 links. It was probably a error or wishfully thinking on an engineers part. I had also seen message threads asking about the 2000 link listings but no one ever reported seeing one.
Recommended Posts
Archived
This topic is now archived and is closed to further replies.