paulbates Posted March 1, 2019 Posted March 1, 2019 34 minutes ago, simplextech said: Mark's plugin uses the REST to update HS devices for status but that doesn't have any correlation with the receipt of the DON/DOF of Insteon traffic. It does if you connect the plugin to an Insteon hub, where no PLM is used 34 minutes ago, simplextech said: Start of test was a Clean system. Testing was perfect. Then I loaded the system with all devices. Results the same. I then added in all of my "programs" into HS3 as events. NO ISSUES. I've ran HS3 for a while within my own system and I've had nearly a thousand devices and over a dozen active plugins and I never have this type of slowness around an "event" not processing. Ok, not sure what's wrong then. Some of my key HA is based on insteon triggering the ISY, motion sensor, switches, keypad keys.. like programs that backstop a motion sensor on that we've discussed in other threads. I travel, if these functions weren't working, my phone would be ringing. The beauty of the ISY vs when I came from HS almost 5 years is that I'm no longer wondering if HS is running or problems with it. Maybe things have improved there, don't know. I also moved because the tech burden of upgrading my HS2 system / scripts to HS3 was harder than moving everything to the ISY Paul
simplextech Posted March 1, 2019 Author Posted March 1, 2019 7 minutes ago, paulbates said: It does if you connect the plugin to an Insteon hub, where no PLM is used ewww.. Insteon hub 7 minutes ago, paulbates said: Ok, not sure what's wrong then. Some of my key HA is based on insteon triggering the ISY, motion sensor, switches, keypad keys.. like programs that backstop a motion sensor on that we've discussed in other threads. I travel, if these functions weren't working, my phone would be ringing. The beauty of the ISY vs when I came from HS almost 5 years is that I'm no longer wondering if HS is running or problems with it. Maybe things have improved there, don't know. I also moved because the tech burden of upgrading my HS2 system / scripts to HS3 was harder than moving everything to the ISY Yeah... something is wrong That's what I'm trying to figure out. The throwing HS3 into the mix was to try and isolate the pieces and it clearly points to the controller not the PLM or network communications. I agree I've started looking at the iSY for polyglot development and the platform looked great and easy to maintain when away. I have no prior experience with HS2 but I've read all about the horror of migrating to HS3 so yeah it makes sense to move from HS2 to ISY. I have almost every system I can think of in my test bed for comparison and I recently added Insteon and the ISY for eval. These results and issues are quite shocking to me.
paulbates Posted March 1, 2019 Posted March 1, 2019 15 minutes ago, simplextech said: ewww.. Insteon hub Yeh I was stubborn and had to try it. The results matched expectations.......
Michel Kohanim Posted March 1, 2019 Posted March 1, 2019 @simplextech, Once you are back on ISY, we can do a remote session. Again, the fact that 50% of the time nothing works, is a big red flag. With kind regards, Michel
simplextech Posted March 2, 2019 Author Posted March 2, 2019 I reset and moved added the following to the ISY with the following steps: Moved the PLM to the same plug I was using for HS Moved the HS PLM to the outlet the ISY PLM was using previously. In HS multiple hops and some errors are shown. Which is a good sign there may be too much noise on that outlet for the PLM. The ISY PLM is now on a "as clean as it gets" outlet. Open Close sensor reset/added to ISY Dual-Band Switch added to ISY Adjacent door has open close sensor still in HS Adjacent switch is same model dual-band switch still within HS ISY Logs so far from a "success" Sat 03/02/2019 17:54:41 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 11 01 LTONRR (01) Sat 03/02/2019 17:54:41 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:41 : [D2D EVENT ] Event [47 FC 4F 1] [DON] [1] uom=0 prec=-1 Sat 03/02/2019 17:54:41 : [ 47 FC 4F 1] DON 1 Sat 03/02/2019 17:54:41 : [D2D-CMP 0003] CTL [47 FC 4F 1] [DON] op=is --> true Sat 03/02/2019 17:54:41 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CF 11 01 LTONRR (01) Sat 03/02/2019 17:54:41 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:41 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:41 : [INST-SRX ] 02 50 47.FC.4F 4C.1B.8A 45 11 01 LTONRR (01) Sat 03/02/2019 17:54:41 : [Std-Cleanup ] 47.FC.4F-->ISY/PLM Group=1, Max Hops=1, Hops Left=1 Sat 03/02/2019 17:54:41 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:42 : [INST-SRX ] 02 50 47.FC.4F 11.01.01 CF 06 00 (00) Sat 03/02/2019 17:54:42 : [Std-Group ] 47.FC.4F-->11.01.01, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:42 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:42 : [INST-SRX ] 02 50 47.FC.4F 11.01.01 CF 06 00 (00) Sat 03/02/2019 17:54:42 : [Std-Group ] 47.FC.4F-->11.01.01, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:42 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:43 : [INST-TX-I1 ] 02 62 50 C9 CF 0F 11 FF Sat 03/02/2019 17:54:43 : [INST-ACK ] 02 62 50.C9.CF 0F 11 FF 06 LTONRR (FF) Sat 03/02/2019 17:54:43 : [D2D EVENT ] Event [47 FC 4F 1] [ST] [255] uom=100 prec=0 Sat 03/02/2019 17:54:43 : [ 47 FC 4F 1] ST 255 (uom=100 prec=0) Sat 03/02/2019 17:54:43 : [INST-SRX ] 02 50 50.C9.CF 4C.1B.8A 2F 11 FF LTONRR (FF) Sat 03/02/2019 17:54:43 : [Std-Direct Ack] 50.C9.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:44 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:44 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:44 : [D2D EVENT ] Event [47 FC 4F 1] [DOF] [1] uom=0 prec=-1 Sat 03/02/2019 17:54:44 : [ 47 FC 4F 1] DOF 1 Sat 03/02/2019 17:54:44 : [D2D-CMP 0004] CTL [47 FC 4F 1] [DOF] op=is --> true Sat 03/02/2019 17:54:44 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:44 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:44 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:44 : [INST-SRX ] 02 50 47.FC.4F 4C.1B.8A 41 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:44 : [Std-Cleanup ] 47.FC.4F-->ISY/PLM Group=1, Max Hops=1, Hops Left=0 Sat 03/02/2019 17:54:44 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:45 : [INST-SRX ] 02 50 47.FC.4F 13.01.01 CB 06 00 (00) Sat 03/02/2019 17:54:45 : [Std-Group ] 47.FC.4F-->13.01.01, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:45 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:45 : [INST-TX-I1 ] 02 62 50 C9 CF 0F 13 00 Sat 03/02/2019 17:54:45 : [INST-ACK ] 02 62 50.C9.CF 0F 13 00 06 LTOFFRR(00) Sat 03/02/2019 17:54:45 : [D2D EVENT ] Event [47 FC 4F 1] [ST] [0] uom=100 prec=0 Sat 03/02/2019 17:54:45 : [ 47 FC 4F 1] ST 0 (uom=100 prec=0) Sat 03/02/2019 17:54:45 : [INST-SRX ] 02 50 47.FC.4F 13.01.01 CB 06 00 (00) Sat 03/02/2019 17:54:45 : [Std-Group ] 47.FC.4F-->13.01.01, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:45 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:45 : [INST-SRX ] 02 50 50.C9.CF 4C.1B.8A 2F 13 00 LTOFFRR(00) Sat 03/02/2019 17:54:45 : [Std-Direct Ack] 50.C9.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:45 : [D2D EVENT ] Event [50 C9 CF 1] [ST] [0] uom=100 prec=0 Sat 03/02/2019 17:54:45 : [ 50 C9 CF 1] ST 0 (uom=100 prec=0) Sat 03/02/2019 17:54:48 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 11 01 LTONRR (01) Sat 03/02/2019 17:54:48 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:48 : [D2D EVENT ] Event [47 FC 4F 1] [DON] [1] uom=0 prec=-1 Sat 03/02/2019 17:54:48 : [ 47 FC 4F 1] DON 1 Sat 03/02/2019 17:54:48 : [D2D-CMP 0003] CTL [47 FC 4F 1] [DON] op=is --> true Sat 03/02/2019 17:54:49 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CF 11 01 LTONRR (01) Sat 03/02/2019 17:54:49 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:49 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:49 : [INST-SRX ] 02 50 47.FC.4F 4C.1B.8A 45 11 01 LTONRR (01) Sat 03/02/2019 17:54:49 : [Std-Cleanup ] 47.FC.4F-->ISY/PLM Group=1, Max Hops=1, Hops Left=1 Sat 03/02/2019 17:54:49 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:49 : [INST-SRX ] 02 50 47.FC.4F 11.01.01 CF 06 00 (00) Sat 03/02/2019 17:54:49 : [Std-Group ] 47.FC.4F-->11.01.01, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:49 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:50 : [INST-TX-I1 ] 02 62 50 C9 CF 0F 11 FF Sat 03/02/2019 17:54:50 : [D2D EVENT ] Event [47 FC 4F 1] [ST] [255] uom=100 prec=0 Sat 03/02/2019 17:54:50 : [ 47 FC 4F 1] ST 255 (uom=100 prec=0) Sat 03/02/2019 17:54:50 : [INST-ACK ] 02 62 50.C9.CF 0F 11 FF 06 LTONRR (FF) Sat 03/02/2019 17:54:50 : [INST-SRX ] 02 50 47.FC.4F 11.01.01 CF 06 00 (00) Sat 03/02/2019 17:54:50 : [Std-Group ] 47.FC.4F-->11.01.01, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:50 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:50 : [INST-SRX ] 02 50 50.C9.CF 4C.1B.8A 2F 11 FF LTONRR (FF) Sat 03/02/2019 17:54:50 : [Std-Direct Ack] 50.C9.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:50 : [D2D EVENT ] Event [50 C9 CF 1] [ST] [255] uom=100 prec=0 Sat 03/02/2019 17:54:50 : [ 50 C9 CF 1] ST 255 (uom=100 prec=0) Sat 03/02/2019 17:54:52 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:52 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:52 : [D2D EVENT ] Event [47 FC 4F 1] [DOF] [1] uom=0 prec=-1 Sat 03/02/2019 17:54:52 : [ 47 FC 4F 1] DOF 1 Sat 03/02/2019 17:54:52 : [D2D-CMP 0004] CTL [47 FC 4F 1] [DOF] op=is --> true Sat 03/02/2019 17:54:52 : [INST-TX-I1 ] 02 62 50 C9 CF 0F 13 00 Sat 03/02/2019 17:54:52 : [D2D EVENT ] Event [47 FC 4F 1] [ST] [0] uom=100 prec=0 Sat 03/02/2019 17:54:52 : [ 47 FC 4F 1] ST 0 (uom=100 prec=0) Sat 03/02/2019 17:54:52 : [INST-ACK ] 02 62 50.C9.CF 0F 13 00 06 LTOFFRR(00) Sat 03/02/2019 17:54:52 : [INST-SRX ] 02 50 47.FC.4F 00.00.01 CB 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:52 : [Std-Group ] 47.FC.4F-->Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:52 : [INST-DUP ] Previous message ignored. Sat 03/02/2019 17:54:54 : [INST-SRX ] 02 50 50.C9.CF 4C.1B.8A 2F 13 00 LTOFFRR(00) Sat 03/02/2019 17:54:54 : [Std-Direct Ack] 50.C9.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sat 03/02/2019 17:54:54 : [D2D EVENT ] Event [50 C9 CF 1] [ST] [0] uom=100 prec=0 Sat 03/02/2019 17:54:54 : [ 50 C9 CF 1] ST 0 (uom=100 prec=0) Sat 03/02/2019 17:54:54 : [INST-SRX ] 02 50 47.FC.4F 4C.1B.8A 4B 13 01 LTOFFRR(01) Sat 03/02/2019 17:54:54 : [Std-Cleanup ] 47.FC.4F-->ISY/PLM Group=1, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:54 : [D2D EVENT ] Event [47 FC 4F 1] [DOF] [0] uom=0 prec=-1 Sat 03/02/2019 17:54:54 : [ 47 FC 4F 1] DOF 0 Sat 03/02/2019 17:54:54 : [D2D-CMP 0004] CTL [47 FC 4F 1] [DOF] op=is --> true Sat 03/02/2019 17:54:54 : [INST-SRX ] 02 50 47.FC.4F 13.01.01 CB 06 00 (00) Sat 03/02/2019 17:54:54 : [Std-Group ] 47.FC.4F-->13.01.01, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:54 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:55 : [INST-TX-I1 ] 02 62 50 C9 CF 0F 13 00 Sat 03/02/2019 17:54:55 : [INST-SRX ] 02 50 47.FC.4F 13.01.01 CB 06 00 (00) Sat 03/02/2019 17:54:55 : [Std-Group ] 47.FC.4F-->13.01.01, Max Hops=3, Hops Left=2 Sat 03/02/2019 17:54:55 : [INST-INFO ] Previous message ignored. Sat 03/02/2019 17:54:55 : [INST-ACK ] 02 62 50.C9.CF 0F 13 00 06 LTOFFRR(00) Sat 03/02/2019 17:54:55 : [INST-SRX ] 02 50 50.C9.CF 4C.1B.8A 2F 13 00 LTOFFRR(00) Sat 03/02/2019 17:54:55 : [Std-Direct Ack] 50.C9.CF-->ISY/PLM Group=0, Max Hops=3, Hops Left=3
kclenden Posted March 3, 2019 Posted March 3, 2019 I would really recommend using a state variable to track the execution of your program(s). Assigning a value to a state variable will show up in your logs and allow you to see specifically whether a program was executed as well as when it was executed. Knowing when it was executed will allow you to look at the DON timestamp and compare it to the timestamp of the program execution (i.e. variable assignment). An additional bonus is that it will make it easier to associate specific communication with specific programs.
simplextech Posted March 3, 2019 Author Posted March 3, 2019 30 minutes ago, kclenden said: I would really recommend using a state variable to track the execution of your program(s). Assigning a value to a state variable will show up in your logs and allow you to see specifically whether a program was executed as well as when it was executed. Knowing when it was executed will allow you to look at the DON timestamp and compare it to the timestamp of the program execution (i.e. variable assignment). An additional bonus is that it will make it easier to associate specific communication with specific programs. Tracking this is no problem. It's the ONLY program in this ISY. However the suggestion is interesting, having a state variable for every program that I would eventually have to use for tracking? Ummm.... sounds like a duplication of work and resources of triggering the program and setting the variable when the execution timing of this ONE program is already slow enough.
kclenden Posted March 3, 2019 Posted March 3, 2019 1 hour ago, simplextech said: However the suggestion is interesting, having a state variable for every program that I would eventually have to use for tracking? Nope. Only need one variable. The value you assign to it will tell you which code is being run. And tracking it does seem to be a problem. You keep saying that 50% of the time when you open the door, nothing happens even though you see communication. So is the program running, or not? Edit: I've done thousands of hours of troubleshooting in my decades of programming, and having more information has never been a problem. Additionally, you seem to be asking others to help you figure out what isn't working. Do you really expect them to wade through your logs without any cues as to when things happened? Edit 2: Deck Lights-On - [ID 001B][Parent 001A] If 'Living Room / Door Sensor / living-room.door-Opened' Status is On Or 'Dining Room / Motion Sensor / dr.Motion-Sensor' Status is On Or 'CL Bedroom / Door Sensor / cl.room.ext.door-Opened' Status is On Then $sCodeTrack = 1 Set 'Deck / Scene / All Deck Lights' Fast On $sCodeTrack = 2 $sCodeTrack = 0 Else - No Actions - (To add one, press 'Action') Add three statements to your program and you'll always know if your program ran. It will definitively tell you whether your program simply didn't run even though a DON was received from the open/close sensor. It will tell you how much time elapsed between the DON being received and the program running. It will tell you how much time elapsed between the program telling the scene to come on and the commands actually being sent. Why would you not want to know these things? If you can definitely show a DON being received, but your program not running, or taking a really long time to run, then you have something that UDI could respond to.
simplextech Posted March 3, 2019 Author Posted March 3, 2019 2 minutes ago, kclenden said: Nope. Only need one variable. The value you assign to it will tell you which code is being run. And tracking it does seem to be a problem. You keep saying that 50% of the time when you open the door, nothing happens even though you see communication. So is the program running, or not? @Michel Kohanim If you see the new info I said I was able to get things to be more reliable. I did have to use HS comm testing to find a new outlet with less noise and brought the comm across all devices to nearly 100% across the board with no filter's. That said things have so far been a lot more reliable. So far 99% with only one failure to recognize a single DOF. Also as I have stated that the program is running and is in a completely isolated environment with no nodeservers or anything else that could be adding any additional load to the ISY. There only 2 devices and 2 programs that are running. So far the programs are running and have been very consistent. However the performance although is steady and consistent is from my stand point what I call slow. It takes a whole 1 second from door open to light switch to turn on. In a literal side by side comparison I have an identical setup of open/close sensor and switch connected to my HS system. I put the HS system PLM on the "bad" outlet that the ISY was using. The HS system speed is in milliseconds almost instant from door open to switch on. Any ideas on this? I do understand the two systems are in different categories (classes) especially around hardware. Which may explain everything.
simplextech Posted March 3, 2019 Author Posted March 3, 2019 15 minutes ago, kclenden said: Edit: I've done thousands of hours of troubleshooting in my decades of programming, and having more information has never been a problem. Additionally, you seem to be asking others to help you figure out what isn't working. Do you really expect them to wade through your logs without any cues as to when things happened? @kclenden Wow... love the attitude. You speak to everyone as if they are some "Kid" fresh off the block without a couple decades of their own experience? This isn't a measuring contest. See the start of this. I came new to ISY looking to develop for it and asking for information on HOW TO TROUBLESHOOT this thing not asking people to read through logs for me. I can read fine but knowing what you're looking for takes either documentation or someone to explain what to look for as there isn't a blatant "ERROR" anywhere in the logs. Yes before (a day ago + the whole week + before) the system was running very poorly with this one problem being only about a 50% success ratio which is poor by all standards and I was looking for guidance on how to troubleshoot and it was requested to POST the logs. So I've been posting. Now your info on the variable for use as a code trace is helpful and was not mentioned before, so thank you for that. I do find it odd that a system like this would not have this in the regular log or a way to enable a program trace without having to manually do it within each program.
Michel Kohanim Posted March 3, 2019 Posted March 3, 2019 @simplextech, Good to know. Still don't understand what comm issues had to do with anything since you had already ruled them out. No? As I mentioned, I have never used HS so I have no clue. This said, I know for a fact that it takes 250m.s. from the PLM to ISY (TX plus ACK). More if controlling a device not a scene (TX, ACK, RX). And 150m.s. to send a command from the PLM. So, at the very minimum, commands from PLM to the end device take 400m.s. Make that round trip plus processing (sensor to PLM, ISY processing, and PLM back to devices) and thus I would say whatever HS is doing requires a medal of honor as it seems to be physical impossibility at least with 2413S. With kind regards, Michel .
simplextech Posted March 3, 2019 Author Posted March 3, 2019 4 minutes ago, Michel Kohanim said: @simplextech, Good to know. Still don't understand what comm issues had to do with anything since you had already ruled them out. No? As I mentioned, I have never used HS so I have no clue. This said, I know for a fact that it takes 250m.s. from the PLM to ISY (TX plus ACK). More if controlling a device not a scene (TX, ACK, RX). And 150m.s. to send a command from the PLM. So, at the very minimum, commands from PLM to the end device take 400m.s. Make that round trip plus processing (sensor to PLM, ISY processing, and PLM back to devices) and thus I would say whatever HS is doing requires a medal of honor as it seems to be physical impossibility at least with 2413S. With kind regards, Michel . @Michel Kohanim, Yes things are much improved. The round trip timing adds up what I'm "seeing". Currently this is testing at a direct to device and not a scene. I will change to a scene for comparison even if it's just a single device. The differences between HS and ISY is the PLM being Serial for ISY and USB for HS which "shouldn't" make any difference at all. The other difference is system hardware of HS is on PC hardware Windows 10 Pro which actually should cause it to be slower Back to the COMM's. In all of the L3 logs that I had previously posted and that I reviewed there were no "errors" that I saw which I posted to see if anyone else saw what I was missing. Hops left all looked acceptable. So with HS I ran multiple runs of the COMM test against different outlets and found one on a mostly isolated circuit where everything ran through 100% after several runs. That's where i moved the ISY to and now everything has been much much better reliability wise. It just occurred to me. Is there a global ISY retry setting or per device only? I've seen it in the advanced section for the devices but not a global one. In HS there is a global retry that is default to 5 command retries. This may explain the reliability of HS even on the "bad" outlet that it is using now.
kclenden Posted March 3, 2019 Posted March 3, 2019 2 hours ago, simplextech said: The differences between HS and ISY is the PLM being Serial for ISY and USB for HS which "shouldn't" make any difference at all. Based on what Michel said, I'm not sure that's a safe assumption. He indicated it takes 250ms from PLM to ISY. That means a half second of the total round trip time is used up by the ISY communicating with the PLM. Or put another way, more than 60% of the round trip time is used up by ISY/PLM communication. Even if the HS PLM is using USB 1.0, the HS/PLM communication is going to be at least 600 times faster than the ISY/PLM. Divide a half second by 600 and I think you've found your difference in execution time.
kclenden Posted March 3, 2019 Posted March 3, 2019 3 hours ago, simplextech said: Wow... love the attitude Right back atcha! You ask for suggestions and then discount them. You took offense at one of Michel's responses as well. I'm seeing a pattern. Wonderful way to endear yourself to the people trying to help.
kclenden Posted March 3, 2019 Posted March 3, 2019 So based on Michel's information about how long it takes to communicate with the PLM, I thought I'd do a real world test. I created a program that sends ON commands to six different devices, followed by sending OFF commands to those same six devices. In other words, the ISY would be dedicated to sending 12 commands consecutively without interruption. I chose this way so that I'd have enough communication to consume several seconds so that I could arrive at an average time it takes the ISY to communicate with the PLM since the logs only show times to the second and not millisecond. I posted the program I used, and the log that resulted below. A quick summary: On average, it took about 125ms for each communication with the PLM. Since the ISY sends a command to the PLM, and then receives an ACK, that adds up to the 250ms stated by Michel. See Note #1 below for how I calculated this. If there's a lot of communication happening, it looks like there can be a significant lag between the ISY receiving the status from a device and it raising a trigger, but I may be misreading the log. Perhaps @Michel Kohanim can weigh in on this. See Note #2 for how I arrived at this conclusion. Using my state variable method of tracking program execution doesn't help at all when trying to tie specific program lines to specific communication, at least not during heavy communication, though it does still confirm program execution. Sorry @simplextech. See Note #3. A lot of outgoing Insteon communication will definitely starve other processes (e.g. other programs) from running. I've certainly seen others on the forum recommend putting WAITs between sending Insteon commands, though usually to avoid communication collisions, but this test reinforces doing it to allow other programs time to run. Note #1: INST-TX-I1 show instances where the ISY wrote data to the PLM. INST-ACK and INST-SRX show instances where the ISY read data from the PLM. Starting at 3:27:06 the PLM started sending the first ON command. For 40 consecutive lines of the log, the ISY is either writing data to the PLM or reading data from the PLM. Those 40 lines span the time from 3:27:06 to 3:27:12. Giving the benefit of the doubt to speed, let's assume the times are 3:27:06.99 and 3:27:12.00. That means it took 5 seconds for the ISY to read/write to the PLM 40 times. 5 seconds/40 = 125ms. Note #2: The log shows 02 50 ... FF LTONRR (FF) and 02 50 ... 00 LTOFFRR(00) for each of the devices. This shows when the ISY reads the data from the PLM with the ON/OFF status update from the device. There is also a [D2D Event] for each of the device's change in status (with one exception) which is when I think the ISY recognizes a status change. Notice that at 3:27:07 the ISY reads the message from 28.F3.CC that it has turned on, but it's not until 3:27:12 that a [D2D Event] is logged. Since I didn't setup any programs to trigger on any of these devices, it could be that internally the ISY knows that the event has occurred, and would have triggered a program to run, and it just took five seconds to create a log entry. But given my note about variables below, I doubt a program would have been given any time to run until 3:27:12 anyway. What also worries me is that there is a log entry at 3:28:08 for the ISY receiving a status update from device 23.BC.6F that is has turned on but there is not a corresponding [D2D Event] for 23.BC.6F turning on. Would a program set to trigger on device 23.BC.6F turning on have failed to run? Note #3: My assignment of values to variables do not show up in the log until the ISY has finished sending all 12 device commands (though not done reading status updates). Though I can't be sure the variables weren't actually changed immediately and not just added to the log five seconds later, when I look at the Variables page, the Last Changed time also shows 3:27:12. The Program: Test Transmit Time - [ID 00AC][Parent 002B] If - No Conditions - (To add one, press 'Schedule' or 'Condition') Then $sCodeTrack = 1 Set 'DR-Ceiling Spots' On $sCodeTrack = 2 Set 'ER-Overhead' On $sCodeTrack = 3 Set 'ER-Sconce' On $sCodeTrack = 4 Set 'FY-Entry Spot' On $sCodeTrack = 5 Set 'FY-Hallway Bank #1' On $sCodeTrack = 6 Set 'FY-Hallway Bank #2' On $sCodeTrack = 7 Set 'DR-Ceiling Spots' Off $sCodeTrack = 8 Set 'ER-Overhead' Off $sCodeTrack = 9 Set 'ER-Sconce' Off $sCodeTrack = 10 Set 'FY-Entry Spot' Off $sCodeTrack = 11 Set 'FY-Hallway Bank #1' Off $sCodeTrack = 12 Set 'FY-Hallway Bank #2' Off $sCodeTrack = 13 $sCodeTrack = 0 Else - No Actions - (To add one, press 'Action') The Results: Sun 03/03/2019 03:27:06 AM : [ Time] 03:27:12 9(0) Sun 03/03/2019 03:27:06 AM : [INST-TX-I1 ] 02 62 28 F3 CC 0F 11 FF Sun 03/03/2019 03:27:06 AM : [INST-TX-I1 ] 02 62 24 A3 83 0F 11 FF Sun 03/03/2019 03:27:06 AM : [INST-TX-I1 ] 02 62 24 64 A1 0F 11 FF Sun 03/03/2019 03:27:06 AM : [INST-TX-I1 ] 02 62 23 BC 6F 0F 11 FF Sun 03/03/2019 03:27:06 AM : [INST-ACK ] 02 62 28.F3.CC 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:06 AM : [INST-TX-I1 ] 02 62 22 A8 47 0F 11 FF Sun 03/03/2019 03:27:07 AM : [INST-SRX ] 02 50 28.F3.CC 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:07 AM : [Std-Direct Ack] 28.F3.CC-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:07 AM : [INST-ACK ] 02 62 24.A3.83 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:07 AM : [INST-SRX ] 02 50 24.A3.83 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:07 AM : [Std-Direct Ack] 24.A3.83-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:07 AM : [INST-ACK ] 02 62 24.64.A1 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:08 AM : [INST-SRX ] 02 50 24.64.A1 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:08 AM : [Std-Direct Ack] 24.64.A1-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:08 AM : [INST-ACK ] 02 62 23.BC.6F 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:08 AM : [INST-SRX ] 02 50 23.BC.6F 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:08 AM : [Std-Direct Ack] 23.BC.6F-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:08 AM : [INST-ACK ] 02 62 22.A8.47 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:09 AM : [INST-SRX ] 02 50 22.A8.47 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:09 AM : [Std-Direct Ack] 22.A8.47-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:09 AM : [INST-TX-I1 ] 02 62 22 AA D7 0F 11 FF Sun 03/03/2019 03:27:09 AM : [INST-TX-I1 ] 02 62 28 F3 CC 0F 13 00 Sun 03/03/2019 03:27:09 AM : [INST-TX-I1 ] 02 62 24 A3 83 0F 13 00 Sun 03/03/2019 03:27:09 AM : [INST-ACK ] 02 62 22.AA.D7 0F 11 FF 06 LTONRR (FF) Sun 03/03/2019 03:27:09 AM : [INST-TX-I1 ] 02 62 24 64 A1 0F 13 00 Sun 03/03/2019 03:27:09 AM : [INST-SRX ] 02 50 22.AA.D7 40.52.35 2F 11 FF LTONRR (FF) Sun 03/03/2019 03:27:09 AM : [Std-Direct Ack] 22.AA.D7-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:10 AM : [INST-ACK ] 02 62 28.F3.CC 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:10 AM : [INST-SRX ] 02 50 28.F3.CC 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:10 AM : [Std-Direct Ack] 28.F3.CC-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:10 AM : [INST-ACK ] 02 62 24.A3.83 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:10 AM : [INST-SRX ] 02 50 24.A3.83 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:10 AM : [Std-Direct Ack] 24.A3.83-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:11 AM : [INST-ACK ] 02 62 24.64.A1 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:11 AM : [INST-SRX ] 02 50 24.64.A1 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:11 AM : [Std-Direct Ack] 24.64.A1-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:12 AM : [INST-TX-I1 ] 02 62 23 BC 6F 0F 13 00 Sun 03/03/2019 03:27:12 AM : [INST-TX-I1 ] 02 62 22 A8 47 0F 13 00 Sun 03/03/2019 03:27:12 AM : [INST-TX-I1 ] 02 62 22 AA D7 0F 13 00 Sun 03/03/2019 03:27:12 AM : [INST-ACK ] 02 62 23.BC.6F 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 1 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 2 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 3 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 4 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 5 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 6 Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [28 F3 CC 1] [ST] [255] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 28 F3 CC 1] ST 255 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [24 A3 83 1] [ST] [255] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 24 A3 83 1] ST 255 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [24 64 A1 1] [ST] [255] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 24 64 A1 1] ST 255 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [22 A8 47 1] [ST] [255] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 22 A8 47 1] ST 255 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 7 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 8 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 9 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 10 Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [22 AA D7 1] [ST] [255] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 22 AA D7 1] ST 255 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [28 F3 CC 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 28 F3 CC 1] ST 0 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [24 A3 83 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 24 A3 83 1] ST 0 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [INST-SRX ] 02 50 23.BC.6F 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:12 AM : [Std-Direct Ack] 23.BC.6F-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [24 64 A1 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 24 64 A1 1] ST 0 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 11 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 12 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 13 Sun 03/03/2019 03:27:12 AM : [VAR 2 3 ] 0 Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [23 BC 6F 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 23 BC 6F 1] ST 0 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [INST-ACK ] 02 62 22.A8.47 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:12 AM : [INST-SRX ] 02 50 22.A8.47 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:12 AM : [Std-Direct Ack] 22.A8.47-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:12 AM : [D2D EVENT ] Event [22 A8 47 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:12 AM : [ 22 A8 47 1] ST 0 (uom=100 prec=0) Sun 03/03/2019 03:27:12 AM : [INST-ACK ] 02 62 22.AA.D7 0F 13 00 06 LTOFFRR(00) Sun 03/03/2019 03:27:13 AM : [INST-SRX ] 02 50 22.AA.D7 40.52.35 2F 13 00 LTOFFRR(00) Sun 03/03/2019 03:27:13 AM : [Std-Direct Ack] 22.AA.D7-->ISY/PLM Group=0, Max Hops=3, Hops Left=3 Sun 03/03/2019 03:27:13 AM : [D2D EVENT ] Event [22 AA D7 1] [ST] [0] uom=100 prec=0 Sun 03/03/2019 03:27:13 AM : [ 22 AA D7 1] ST 0 (uom=100 prec=0)
larryllix Posted March 3, 2019 Posted March 3, 2019 I don't believe any of the i/o processing is done until the program is completely finished, since there was no Waits or repeats in the program. You are most likely ony measuring the Insteon protocol speed for commands sent from ISY. If the end devices are moved further away, and hops are required via other Insteon repeaters more time may elapse. These speeds should not change from one box to another. You could repeat the test process trying Wait 0 seconds between lines to see if anything changes. If ISY processing speeds are in question I doubt you will ever find any delays unless you can measure microseconds. I ran a similar capability X10 system back in the 1980-90s using a 40 MHz 80486 single core system, and no delays were noticeable in that system, running at 1/15th the speed using a Windows O/S in the background. Any delays are all in the I/O and protocol.
simplextech Posted March 3, 2019 Author Posted March 3, 2019 8 hours ago, kclenden said: Right back atcha! You ask for suggestions and then discount them. You took offense at one of Michel's responses as well. I'm seeing a pattern. Wonderful way to endear yourself to the people trying to help. @kclenden, Even with our snarkiness it motivated further investigation. The test program you did was excellent and more so you provided explanation on the log info which I can now understand the log entries to better read them myself. I apologize for my snarkiness, it was not professional and I was cranky as this has been bugging me.
adamthp Posted March 3, 2019 Posted March 3, 2019 I gotta say, I kind of love it when people get cranky on here and start flexing some muscle. It is a true opportunity to learn some real insight. No offense meant here at all, but with all this back and forth I have really picked up a lot. So from one innocent bystander, thanks for taking the time to hash this one out.
larryllix Posted March 3, 2019 Posted March 3, 2019 5 minutes ago, adamthp said: I gotta say, I kind of love it when people get cranky on here and start flexing some muscle. It is a true opportunity to learn some real insight. No offense meant here at all, but with all this back and forth I have really picked up a lot. So from one innocent bystander, thanks for taking the time to hash this one out. Not an innocent bystander any more! Troubleshooting is very stressful at times.
simplextech Posted March 3, 2019 Author Posted March 3, 2019 5 minutes ago, larryllix said: Troubleshooting is very stressful at times. But that's half the fun I don't like hitting a "problem" and not knowing how to troubleshoot it or what I think is a problem may not be and it's actually "normal" but being "new" to something it doesn't seem normal to me so I start to question it.
larryllix Posted March 3, 2019 Posted March 3, 2019 1 minute ago, simplextech said: But that's half the fun I don't like hitting a "problem" and not knowing how to troubleshoot it or what I think is a problem may not be and it's actually "normal" but being "new" to something it doesn't seem normal to me so I start to question it. Remember three smileys is the international coding for "Please don't hit me!"
kclenden Posted March 4, 2019 Posted March 4, 2019 14 hours ago, larryllix said: You are most likely ony measuring the Insteon protocol speed for commands sent from ISY. If the end devices are moved further away, and hops are required via other Insteon repeaters more time may elapse. These speeds should not change from one box to another. Thanks. That's what I was trying to measure. I wanted to keep the ISY busy with enough communication between it and the PLM so that I could get a sense of how long each ISY/PLM data session took to complete. I agree that these speeds should not change from one Serial PLM to another Serial PLM, but a USB PLM has a much faster communication channel (at least 12Mbs) so in theory a PC could communicate with a USB PLM in much less time than an ISY can communicate with a Serial PLM (19,200 Kbps). Having just typed all that, I checked the Smarthome.com page for the specs on the 2413U and 2413S PowerLinc modems. In both cases, under specs it lists a baud rate of 19,200 Kbps. I don't know if that's simply poor editing on Smarthome's part or if it's accurate, but I've never seen any USB device list a baud rate before. Based on simplextech's experience, I'd bet money that a USB PowerLinc Modem communicates with the device it's connected to faster than the ISY communicates with a Serial PowerLinc Modem because as you said, the ISY processing speed should be plenty fast enough to not be a factor. Having started my computer experience with a 1.77 Mhz Z80 CPU that had no trouble keeping up with 19.2K speeds, I agree with you about the ISY processing speed. If more hops were involved (for the round trip message from the PLM to the device and back) it would delay when the first [Std-Direct Ack] appeared in the log, but not having to process a [Std-Direct Ack] would have allowed the ISY to continue sending commands or receiving ACKS from the PLM ([INST-TX-I1] and [INST-ACK]) with the net result that all commands were sent out faster and then the ISY would just be waiting for replies from the devices. The fact that several [Std-Direct Ack] are able to sneak in between the [INST-TX-I1] and [INST-ACK] reinforces the idea that it takes time for the ISY to communicate with the PLM. Insteon devices are designed not to talk over each other, so if the PLM was pumping out ON commands, one right after the other, the devices receiving those command would wait until the power line was clear before they sent back their response.
mwester Posted March 4, 2019 Posted March 4, 2019 In all probability, the USB PLM is actually a serial PLM with a USB->serial chip inside. That's how a lot of legacy serial devices have moved into the USB world. So the 19200 baud rate thing may well apply to both. If I could find my USB PLM right now, I'd plug it into a Linux machine, and see what it is identified as -- "lsusb" is the command. I'm betting the id will map back to one of several common USB->serial chips out there.
kclenden Posted March 4, 2019 Posted March 4, 2019 With a little googling, found this blurb from Smarthome about the USB Modem: Congratulations and Introduction PowerLinc USB is the world's first Universal Serial Bus (USB) based transmitter and receiver for X10/PLC (Powerline Carrier) control. Unlike previous solutions that used the slower-speed RS-232 Com Port and required the use of a dedicated interrupt control line (IRQ), PowerLinc USB uses the newer and more flexible USB channel now found on nearly all computers. USB ports support higher speeds and multiple devices can be attached to the computer at the same time. It implies the USB PowerLinc is faster but could just be marketing speak. USB_PowerLinc_Blurb_1132U_web.pdf
kclenden Posted March 4, 2019 Posted March 4, 2019 6 minutes ago, mwester said: If I could find my USB PLM right now, I'd plug it into a Linux machine, and see what it is identified as -- "lsusb" is the command. I'm betting the id will map back to one of several common USB->serial chips out there. You may well be right. Still, when trying to explain the significant difference in speed that simplextech saw, an obvious difference between PLMs seems tempting as the ultimate root cause. ?
Recommended Posts
Archived
This topic is now archived and is closed to further replies.