Delays with version 3.0.1.124

[Rvtravlr]

Just the .exe? I do run nightly backups.

[waynehead99]

Should be all you need yea.

[Rvtravlr]

Thank you Wayne. Also for testing.

[randy]

I have had a few messages asking about the events I used for generating the delay testing. I use a Cooper duplex outlet as the device, since it supports instant status. The first Event sets it all up. It makes sure that I want the tests to be running, then it makes sure the outlet is off, starts a timer and then turns the outlet On.



The second event is triggered when the outlet reports it is On and turns it back Off.



A third Event is triggered when the outlet reports that it is Off



The timer is stopped and its value is written to the log. This gives me the time it takes for a full On-Off cycle.

The last Event is just a cleanup, if the outlet is not turned back off within 1 minute.



I use a master timing event for all testing, so that tests don't walk over each other. For this simple test replace the manual trigger in the first event with a recurring trigger. I do it every 3 minutes since that is the schedule of my master test event trigger.

[Rvtravlr]

Randy,

Sort of OT, but why do you use changes and becomes instead of was set?

Thanks

[randy]

Randy,

Sort of OT, but why do you use changes and becomes instead of was set?

Thanks

Because I want to make sure the value actually changes. A "set" is true, even if a device's value doesn't change. If a device is On and you send a command to turn it On, it is "set", but it hasn't changed.

[Rvtravlr]

Because I want to make sure the value actually changes. A "set" is true, even if a device's value doesn't change. If a device is On and you send a command to turn it On, it is "set", but it hasn't changed.

Thanks

[Rvtravlr]

.126 crashed HS3.0.0.300

Dropped .98 back into folder, thanks to Wayne for that info, and now response is much better.

Why do things regress with new iterations of the PI?

[bebaldin]

.126 is installed here and is working well right now. There are no delays. It will take some time to tell if it is improved. I will post back after using it for a while.

Huge improvement for me on .126 here. Most light activations are back to nearly instantaneous, and have remained so all day. I still have a few bugs to work out (mostly caused by me trying anything to fix the issue) but so far 126 looks good. Will update as I get a couple of days of use on the system.

[waynehead99]

So I agree that when its working, it is snappy. I did have about a 10 second delay I noticed at 4 AM this morning when I walked thru my hallway. I just looked at the logs and noticed there were some significant delays from the test I mimicked from Randy thru the night. This is a time when there is really low activity on the house and server (Server is an 8 Core CPU with gobs of memory and very low utilization). This shows there is a problem, but I don't know what else I could provide. I have a lot more delays then I have copied here in this post, all similar times. I am on .126

Rich, what else can I get you to help in your investigation?

[rjh]

Really don't know what is going on, I cannot see any changes from .87 to 124 that would affect timing.

To help, can you enable the debug logging. Click on the plugin name on the plugins page, then check the box "Enable Detailed Logging to File". I would only do this if you are on Windows as with Linux it will be hard to get at the files.

Please delete any old log files you might have in "Debug Logs" folder.

If you see a delay, please send me the log files along with the time of the delay and the device that was delayed. Please email them to me directly at rjh at homeseer.com

[randy]

Really don't know what is going on, I cannot see any changes from .87 to 124 that would affect timing.

To help, can you enable the debug logging. Click on the plugin name on the plugins page, then check the box "Enable Detailed Logging to File". I would only do this if you are on Windows as with Linux it will be hard to get at the files.

Please delete any old log files you might have in "Debug Logs" folder.

If you see a delay, please send me the log files along with the time of the delay and the device that was delayed. Please email them to me directly at rjh at homeseer.com

I will do this, if I can. The problem lies with the fact that the delays are so random. For now, I will enable debug logging, then send you the debug logs as well as any log entries showing a delay in my test event. At least then you can narrow it down as far as time.

V.126 is interesting that we have only actually noticed one delay yesterday, yet they can be seen in the log with my delay test.

It is also worth noting that enabling Z-Wave detailed debug logging can slow down Z-Wave response a little. Not by a large amount but IIRC it is less than a second.

[rjh]

Is the delay always with your minimote? Have you seen a delay with a motion sensor? Have you noticed a delay with HS just running an event and controller devices? I am trying to figure out if the delay is with incoming packet processing or outgoing.

Also, does it ever happen immediately after starting HS, or does it always take some time? Maybe there is a memory issue.

I will do this, if I can. The problem lies with the fact that the delays are so random. For now, I will enable debug logging, then send you the debug logs as well as any log entries showing a delay in my test event. At least then you can narrow it down as far as time.

V.126 is interesting that we have only actually noticed one delay yesterday, yet they can be seen in the log with my delay test.

It is also worth noting that enabling Z-Wave detailed debug logging can slow down Z-Wave response a little. Not by a large amount but IIRC it is less than a second.

[waynehead99]

Rich,
Just sent you some logs. I had a delay show up in my test. Personally I notice the delays on my motions and lights. A restart of the plugin does resolves the issue (the delays seem to start getting worse until a restart is done). I don't touch the znet at all, probably hasn't been bounced in 6 months. I am also trying to look at other things that HS might be doing at the time that could bring everything to a halt during the time. I remember in the past when we had the issue of events locking everything up for a bit, but I haven't seen anything similar. Right now it just looks like zwave freezes up for a bit.

[randy]

Is the delay always with your minimote? Have you seen a delay with a motion sensor? Have you noticed a delay with HS just running an event and controller devices? I am trying to figure out if the delay is with incoming packet processing or outgoing.

Also, does it ever happen immediately after starting HS, or does it always take some time? Maybe there is a memory issue.

Not just the MiniMote. It is just a really easy way to see the delay. It is noticeable with all motion controlled lighting. All of my motion sensors are hard wired to a DSC panel and communicate with HS through the Envisalink plug-in. We also see the delays with "scenes" from HS switches and dimmers. It will also show up with lights being controlled by other lights through events. I do not use the new device linking you added, I use Spud's Easy Trigger to synchronize devices. I have seen the delays when controlling devices from HSTouch or even the device manager. I have seen delays in commands being executed in my Z-Wave thermostats.

In no case have I seen a delay in the initiating device (PIR, door switch, event, etc.), unless the initiating device is Z-Wave. The most irritating and frustrating delay is walking into a dark room in the basement and having it take 5-20 seconds for the lights to go on. There is a light that goes on immediately on the PIR. If I check the log I will see the event triggered by the PIR with 5-20 seconds elapsing before the device is turned on. Beyond that I have no idea where the delay is. It is clearly somewhere between the event Action controlling the device and the device responding to the command. It could be a delay in the command going out or the device responding. Once a device is controlled I have not seen a delay in that being returned to the log.