Announcement

Collapse
No announcement yet.

Zwave command delay due to commands being queued ?

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

  • Zwave command delay due to commands being queued ?

    I have problems with devices being very slow to respond to on/off commands. This normally happens after my HS3 has been running for a few hours. Straight after a reboot everything is instant. When I click on the zwave plugin (In plugins manage) I see this (but no idea what it means)

    Uptime: 4 Hours, 23 Minutes, 13 Seconds

    Network E075A8D5
    E075A8D5 Z-Health
    Disabled Node ID: 1
    # Nodes: 55 CMD Q: 0 Poll Q: 0 WakeUp Q: 0 TX Q: (empty) Frames In: Total=47057, MGD=65 Report Buff: 48

    It seems to me when the system is slow, the Report Buff number seems high.

    Can that be ? How can I find out what is being queued and by what ?

  • #2
    I'm far from a guru on this, but I think most people recommend turning Z-Health off and I'm a bit of at a loss to explain "Disabled Node ID: 1," which I think should be your Z-Wave controller.....
    HomeSeer Version: HS3 Pro Edition 3.0.0.500
    Operating System: Microsoft Windows 10 Pro - Work Station

    Enabled Plug-Ins:
    2.1.0.119: AmbientWeather | 3.0.21.0: BLLock | 2.0.24.0: BLUPS | 1.3.6.0: Device History | 3.0.0.56: EasyTrigger | 3.1.0.7: MeiHarmonyHub | 3.0.6681.34300: UltraCID3 | 3.0.6644.26753: UltraLog3 | 3.0.6554.33094: UltraMon3 | 3.0.0.91: weatherXML | 3.0.1.245: Z-Wave | 3.0.51: HS Touch Designer | 3.0.0.40 Z-Seer+

    Comment


    • #3
      I have zhealth disabled, I knew it could cause issues. Might look as if its rurned on on my post but it isnt. The disabled node 1 is a secondary controller which i wanted to experiment with. Itbhas no devices attached to it and dont have time to play with it so i unplugged it.
      I have had these issues before introducing the secondary controller. I actually thought of having that to try and improve on zwave communication but it doesnt look as if that is the problem. Seems more likely its flooded with queued zwave commands or polls

      Comment


      • #4
        Originally posted by ewkearns View Post
        I'm far from a guru on this, but I think most people recommend turning Z-Health off and I'm a bit of at a loss to explain "Disabled Node ID: 1," which I think should be your Z-Wave controller.....
        It is a problem with the way he grabbed text. It is really
        Z-Health Disabled and that the Node ID of the controller is 1.

        Here is a screenshot:

        Click image for larger version

Name:	Capture.PNG
Views:	1
Size:	143.2 KB
ID:	1190738

        I don't think the report buffers are signs of a problem, the queues are usually where things back up. I did stop my system from coming to a dead halt when a node becomes unresponsive by changing the send timeout to 2 seconds.

        Generally my Z-Wave is virtually instant. When I do see a delay it is now 1-3 seconds at most and the delays are very infrequent. When there are delays, I am still unable to confirm if it is in the Z-Wave network or in HomeSeer. There have been times that I have seen HomeSeer slow down in all respects and others when it only seems to be Z-Wave. Several times in the last month I have seen the Z-Wave plug-in CPU usage spike and a restart cures it. My average CPU usage is around 20% and when the Z-Wave plug-in spikes just the plug-in executable can go to 40-50% with total CPU at 55-65%. On the instances where I have caught it, the Z-Wave network has a longer delay, but so does everything else in HS (Event Page and Event editing and Device Manager page loading).

        I have yet to find anything that points to why this is happening.
        Randy Prade
        Aurora, CO
        Prades.net

        PHLocation - Pushover - EasyTrigger - UltraECM3 - Ultra1Wire3 - Arduino

        Comment


        • #5
          Originally posted by rprade View Post
          It is a problem with the way he grabbed text. It is really
          Z-Health Disabled and that the Node ID of the controller is 1.

          Here is a screenshot:

          [ATTACH]60961[/ATTACH]
          by changing the send timeout to 2 seconds.
          Please tell me how to change this timeout

          Comment


          • #6
            goto Plugins-->Manage, then click on the zwave plugin link.

            Every once in a while I will get a zwave command delay of about 33 seconds. However, when this happens my Que is empty and the web interface responds normally. No idea whats going on.
            If it ain't broke, don't fix it!

            Comment


            • #7
              I've also been seeing sporadic delays in Z-wave devices turning on. Thought moving to the beta plugin 3.0.1.116 would help but I'm not seeing any consistency in the issues or when they're working flawlessly.

              I've been seeing a delays of as little as 5 seconds and as long as up to a minute but there is 0 errors or delays present in my logs.

              Example: I have a light configured in my laundry room configured to turn on when the door sensor changes to open, and the light to turn off when the door sensor changes to closed. Upon the first open of the day, seeing a delay between 5-30 seconds. Once I close it though, that close event fires immediately and the light turns off. No queues anywhere I can see. Almost like the door sensor needs to be 'woken up' before events fire off correctly on it's status change as far as I can figure.

              Is there anyway to help try to narrow down where the issue is occurring? Maybe some more verbose logging for the z-wave plugin somewhere that I'm missing? I've had this system for a few years now and didn't experience any delays until this year when I added around 10 more physical devices. All virtual devices and events triggered off them seem to work with 0 delays that I've seen.

              Comment


              • #8
                What version of the plugin is everyone running that has issues?

                I am still on .87. Each time I try to go into the 100 series, I kept seeing crazy delays after a few hours of running. I'm kinda at a point though that I need to update because of some fixes in the plugin, but I haven't been able to figure out the delays in the betas either. As it stands currently, if you are running the betas and having issues, go back to the public release and I am guessing/betting your issue of delays goes away.

                Comment


                • #9
                  I'm on the latest beta but I'm going to roll back and see if that makes a difference
                  If it ain't broke, don't fix it!

                  Comment


                  • #10
                    I've rolled back to 3.0.1.87 and have not seen any delays yet but they mostly seemed to manifest after 2-3 days of the plugin running. I'll report back if I see anything.
                    Last edited by MorkaiTheWolf; May 28th, 2017, 09:13 PM.

                    Comment


                    • #11
                      I've just encountered a delay and grabbed the following as soon as I saw it.

                      Code:
                      May-29 4:12:59 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Hallway Light Set to 99
                      May-29 4:12:59 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Left Light Set to 99
                      May-29 4:12:59 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Right Light Set to 99
                      May-29 4:12:37 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Right Light to On (99)
                      May-29 4:12:37 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Left Light to On (99)
                      May-29 4:12:37 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Hallway Light to On (99)
                      May-29 4:12:37 AM	 	Event	Event Trigger "Lighting Bedroom Lights On"
                      May-29 4:12:37 AM	 	Event	Event Trigger "Lighting Bedroom Lights on when door opened"
                      May-29 4:12:37 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Door Sensor Set to On/Open/Motion
                      The light's didn't actually turn on until the 4:12:59AM portion. Is there a difference when it's written with a type of "Device Control" vs when it's written with a type of "Z-Wave"? That's the only noticeable difference I see.

                      To further expand, I've pulled some more logs and can see that no gap was exhibited between when the event fired and when the devices actually turned on.

                      Lights turning off
                      Code:
                      May-29 3:45:49 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Hallway Light Set to 0
                      May-29 3:45:49 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Left Light Set to 0
                      May-29 3:45:49 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Right Light Set to 0
                      May-29 3:45:49 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Right Light to Off (0)
                      May-29 3:45:49 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Left Light to Off (0)
                      May-29 3:45:49 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Hallway Light to Off (0)
                      May-29 3:45:49 AM	 	Event	Event Trigger "Lighting Bedroom Lights Off"
                      May-29 3:45:49 AM	 	Event	Event Trigger "Lighting Bedroom Lights on when door closed - NIGHT"
                      And about twenty minutes earlier when I went into the room to grab something:
                      Code:
                      May-29 3:26:16 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Hallway Light Set to 99
                      May-29 3:26:16 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Left Light Set to 99
                      May-29 3:26:16 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Right Light Set to 99
                      May-29 3:26:16 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Right Light to On (99)
                      May-29 3:26:16 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Left Light to On (99)
                      May-29 3:26:16 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Hallway Light to On (99)
                      May-29 3:26:16 AM	 	Event	Event Trigger "Lighting Bedroom Lights On"
                      May-29 3:26:16 AM	 	Event	Event Trigger "Lighting Bedroom Lights on when door opened"
                      May-29 3:26:16 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Door Sensor Set to On/Open/Motion
                      With what I've seen so far, I can see the 20 second difference between "Device Control" and "Z-wave". It seems the "Z-Wave" portion actually turns them on (which makes sense), but my event fired and matched all conditions so I'm not sure what could have created that delay between the device control and z-wave portions.

                      Comment


                      • #12
                        I rolled back to the official release as well. I haven't noticed any delays as of yet, but that doesn't mean they haven't happened. The last delay event I had was consistent with your observations, Device control from HSTouch, then zwave and actual control of the device much later.

                        Apr-14 7:43:17 AM Z-Wave Device: 1st Floor Main Heater Set to 0
                        Apr-14 7:42:28 AM Device Control Device: 1st Floor Main Heater to Off (0) by/from: CAPI Control Handler
                        If it ain't broke, don't fix it!

                        Comment


                        • #13
                          MorkaiTheWolf,

                          You can enable additional logging for zwave if you go to manage plugins and click on the zwave link. It will eat up a lot of disk space but could provide additional clues.
                          If it ain't broke, don't fix it!

                          Comment


                          • #14
                            Originally posted by happnatious1 View Post
                            MorkaiTheWolf,

                            You can enable additional logging for zwave if you go to manage plugins and click on the zwave link. It will eat up a lot of disk space but could provide additional clues.
                            Looks like I have a bit free so I'll enable that and see if it reports anything useful. Thanks for the tip happnatious1.

                            Comment


                            • #15
                              Observed another delay. This was around 11 seconds as seen in the logs but not sure if having debug logging could be contributing here.

                              For reference, node numbers relate to the following devices:
                              Node 10: Bedroom Light - Right
                              Node 11: Bedroom Light - Left
                              Node 9: Hallway Light
                              Node 31: Bedroom Aeon Labs Multilevel Sensor (One of those aeotec 6 in 1 sensors)
                              Node 30: Same type of sensor as node 31, but on the other side of the wall.

                              Code:
                              May-29 7:57:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 10 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 7:57:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 11 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 7:57:22 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Hallway Light Set to 99
                              May-29 7:57:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 9 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 7:57:22 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Left Light Set to 99
                              May-29 7:57:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 11 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 7:57:22 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Right Light Set to 99
                              May-29 7:57:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 10 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 7:57:18 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_MULTILEVEL_V2
                              May-29 7:57:12 AM	 	Z-Wave	ApplicationCommandHandler from node 31 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 7:57:11 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Right Light to On (99)
                              May-29 7:57:11 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Left Light to On (99)
                              May-29 7:57:11 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Hallway Light to On (99)
                              May-29 7:57:11 AM	 	Event	Event Trigger "Lighting Bedroom Lights On"
                              May-29 7:57:11 AM	 	Event	Event Trigger "Lighting Bedroom Lights on when door opened"
                              May-29 7:57:11 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Door Sensor Set to On/Open/Motion
                              Any thing else I could do to try and simulate the issue? Almost looks like it's timing out to node 30 before continuing but it's odd it didn't write out any kind of timeout info.

                              EDIT: Another delay just observed in trying to force the issue.

                              Code:
                              May-29 8:13:32 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 10 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 8:13:31 AM	 	Z-Wave	ApplicationCommandHandler from node 5 HANDLING: COMMAND_CLASS_SENSOR_BINARY_V2 Frame(7)=3
                              May-29 8:13:30 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 11 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 8:13:30 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Hallway Light Set to 99
                              May-29 8:13:30 AM	 	Z-Wave	Device: 1st Floor Entertainment Center Relative Humidity Set to 36 (%)
                              May-29 8:13:29 AM	 	Z-Wave	ApplicationCommandHandler from node 18 HANDLING: COMMAND_CLASS_METER_V2 Frame(7)=2
                              May-29 8:13:29 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:28 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:28 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 9 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 8:13:28 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Left Light Set to 99
                              May-29 8:13:28 AM	 	Z-Wave	Device: 1st Floor Bedroom Right Table - Watts Set to 13.524 (13.524 Watts)
                              May-29 8:13:27 AM	 	Z-Wave	ApplicationCommandHandler from node 17 HANDLING: COMMAND_CLASS_METER_V2 Frame(7)=2
                              May-29 8:13:25 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 11 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 8:13:25 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Right Light Set to 99
                              May-29 8:13:24 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 10 (UnSecured) CC=COMMAND_CLASS_SWITCH_MULTILEVEL_V2
                              May-29 8:13:24 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:23 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:22 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_MULTILEVEL_V2
                              May-29 8:13:20 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_MULTILEVEL_V2
                              May-29 8:13:19 AM	 	Z-Wave	Device: 1st Floor Entertainment Center Temperature Set to 77.9 (F)
                              May-29 8:13:19 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:19 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_MULTILEVEL_V2
                              May-29 8:13:17 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_MULTILEVEL_V2
                              May-29 8:13:17 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_SENSOR_BINARY_V2 Frame(7)=3
                              May-29 8:13:16 AM	 	Z-Wave	ApplicationCommandHandler from node 31 HANDLING: COMMAND_CLASS_SENSOR_MULTILEVEL_V2 Frame(7)=5
                              May-29 8:13:15 AM	 	Z-Wave	ApplicationCommandHandler from node 30 HANDLING: COMMAND_CLASS_BATTERY Frame(7)=3
                              May-29 8:13:14 AM	 	Z-Wave	Aeon Labs Aeotec - Z-Stick Gen5: Sending to node 30 (UnSecured) CC=COMMAND_CLASS_SENSOR_BINARY_V2
                              May-29 8:13:14 AM	 	Jon00_RCCNM	[Device1] Client response: OK
                              May-29 8:13:14 AM	 	Device Control	Device: 1st Floor Entertainment Center Entertainment Center - Right to Off (0)
                              May-29 8:13:14 AM	 	Device Control	Device: 1st Floor Entertainment Center Entertainment Center - Left to Off (0)
                              May-29 8:13:14 AM	 	Event	Event Trigger "Entertainment Center Lights Off"
                              May-29 8:13:14 AM	 	Event	Running script in background: C:/Program Files (x86)/HomeSeer HS3/scripts/Jon00RCCNMHS3.vben("Main","1||muteon")
                              May-29 8:13:14 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Right Light to On (99)
                              May-29 8:13:14 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Left Light to On (99)
                              May-29 8:13:14 AM	 	Event	Event Trigger "Work Events Silence Desktop PC"
                              May-29 8:13:14 AM	 	Device Control	Device: 1st Floor Bedroom Bedroom - Hallway Light to On (99)
                              May-29 8:13:14 AM	 	Event	Event Trigger "Work Events Bedroom TV Startup"
                              May-29 8:13:14 AM	 	Event	Event Trigger "Lighting Bedroom Lights On"
                              May-29 8:13:14 AM	 	Event	Event Trigger "Lighting Bedroom Lights on when door opened"
                              May-29 8:13:13 AM	 	Z-Wave	Device: 1st Floor Bedroom Bedroom - Door Sensor Set to On/Open/Motion
                              May-29 8:13:13 AM	 	Z-Wave	ApplicationCommandHandler from node 5 HANDLING: COMMAND_CLASS_SENSOR_BINARY_V2 Frame(7)=3
                              Included the whole snippet from when I triggered the event to when it completed.
                              Last edited by MorkaiTheWolf; May 29th, 2017, 08:15 AM. Reason: Didn't want to create multiple posts just updating a log.

                              Comment

                              Working...
                              X