Announcement

Collapse
No announcement yet.

Execution delay

Collapse
This topic is closed.
X
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    Execution delay

    RJ,
    A while ago I asked about a warning in my log referencing a call to a function that has been replaced with a newer version. Since then I have added the ACRF plug-in and am using it to detect X10 RF signals to avoid cluttering up the power line with them. That plug-in sets a flag that SG uses to take action.

    Recently, as I've increased the number of these, I've noticed increasingly long delays, sometimes minutes, before the action actually occurs. In the following thread I asked about the ACRF plug-in, but the response was that the problem is coming from elsewhere. The only other source is the SG plug-in. Have those calls be updated in a new version of the plug-in?

    http://board.homeseer.com/showthread.php?t=117625
    Mike____________________________________________________________ __________________
    HS3 Pro Edition 3.0.0.548, NUC i3

    HW: Stargate | NX8e | CAV6.6 | Squeezebox | PCS | WGL 800RF | RFXCOM | Vantage Pro | Green-Eye | Edgeport/8 | Way2Call | Ecobee3 | EtherRain | Ubiquiti

    #2
    Hi Mike-

    I'm a bit stumped here. What are these warning messages exactly? If you have a debug log that would be especially helpful in solving this.
    -RJ (HomeSeer Tech)

    Comment


      #3
      RJ,
      I'm not sure what you mean by a debug log, but here are some samples from the HS log to illustrate. In this case I'm deliberately triggering a motion detector while watching the log.

      Here's one with the warning, but no delay. A9 should cause [25 to go on, and it does. (Notice also the '1/4' replacing the JDS designator.)



      Here's a longer sequence with several different examples. A7 should cause [26 to go on. Here A7 and A9 go on at 48:22, but the flags don't change for 20 sec and in that time A7 goes on again. Then they seem to be working as expected a few seconds later.



      Unfortunately, the problem is not consistent and does not exhibit its really long delays while I'm watching the log. Here's an example I pulled from yesterday's log. Notice four A9 On signals, then four flag changes 30 sec later.

      1Also, it isn't as simple as I thought when I wrote my note yesterday. There are times when the error warning does not occur at all, but there are still long delays. And when I watch the SG log and the HS log together, there are times when the flag change in HS is reflected immediately in WinEVM, and there are times when there is a long lag. (SG has an action it should take when the flag changes, so I'm not just looking for WinEVM to reflect the change in flag state, I'm looking for it to reflect the SG action.) The SG lag is always present when the lag is evident in HS, but even when HS changes the flag, there can still be an additional lag before SG takes action.

      As a check, another set of events change flags and a mutual variable. I have never seen that interchange experience a lag. Only the events that are initiated by an X10 RF signal processed by the ACRF plug-in appear to be affected. That's why I sent the original query to that forum.
      Mike____________________________________________________________ __________________
      HS3 Pro Edition 3.0.0.548, NUC i3

      HW: Stargate | NX8e | CAV6.6 | Squeezebox | PCS | WGL 800RF | RFXCOM | Vantage Pro | Green-Eye | Edgeport/8 | Way2Call | Ecobee3 | EtherRain | Ubiquiti

      Comment


        #4
        More info

        RJ,
        I need to take back part of what I said in my previous note. The intermittent nature of the delay is making it difficult to be definite about when and why it happens. I've been paying more attention to my 'heartbeat' exchange between HS and SG and it appears to be happening there as well. Here's an example from the log:

        One cycle of the HS side of the heartbeat.The SG side of the heartbeat as reflected in the HS log.
        An X10 RF motion detector.58 AM - HS Heartbeat - Finished
        The next HS side of the heartbeat.

        Notice that in one case the script executed in one second. In the second, there was a delay at the end of the script of 30 sec.

        For reference, here is a copy of the script:

        Code:
        Sub Main
              Dim lngHBeat_val
           
           
           ' Get value of heartbeat variable
              lngHBeat_val = hs.DeviceValueByName("JDS HBeat")
              hs.WriteLog "SG Heartbeat", CStr(lngHBeat_val)
           
           ' Stargate increments the variable once each minute
           ' HomeSeer decrements it
           
           ' The value of the variable should stay between 9 and 11
           
           ' If the heartbeat variable is less than 11, decrement it
           ' Stop when it reaches 1
              If lngHBeat_val < 11 And lngHBeat_val >1 Then
           	 lngHBeat_val = lngHBeat_val - 1
           
           ' After 5 minutes with no increment by SG clear the SGRunning flag
           	 If lngHBeat_val = 5 Then
           	   hs.SetDeviceStatusByName "SGRunning", 3
           	   hs.WriteLog "HS Heartbeat", CStr(lngHBeat_val)
           '	   hs.WriteLog "SG", CStr(lngHBeat_val)
           	 End If
           
           ' If the heatbeat variable is greater than 10, then reset it to 10
              Else
           	  lngHBeat_val = 10
              End If
           
           ' Store the heartbeat value
              hs.SetDeviceValueByName "JDS HBeat", lngHBeat_val
           '   hs.WriteLog "HS Heartbeat", CStr(lngHBeat_val)
              hs.WriteLog "HS Heartbeat", "Finished"
             
           End Sub
        The delay appears to come after the value of (JDS HBeat) has been set, but before the 'Finished' message is written to the log.

        Is there something I'm doing in the script that could be causing the delay?
        Mike____________________________________________________________ __________________
        HS3 Pro Edition 3.0.0.548, NUC i3

        HW: Stargate | NX8e | CAV6.6 | Squeezebox | PCS | WGL 800RF | RFXCOM | Vantage Pro | Green-Eye | Edgeport/8 | Way2Call | Ecobee3 | EtherRain | Ubiquiti

        Comment


          #5
          Refined question

          One further update. Once I realized that my heartbeat script was experiencing a delay I removed it from the event so that it no longer executes. Sure enough, the delays in other events are no longer showing up. (Which isn't to say they don't occur, it's just that because the heatbeat script was running once a minute and intermittently hanging, it showed up as a dely in other events fairly often.)

          So, my new question is an extension of the one I asked in my last post. Is there a problem in my script that causes it to hang? What can I change to accomplish the same thing without causing the script to hang?

          If the problem isn't in the script, do I need to create a help ticket? And, if so, what am I asking for help to resolve?
          Mike____________________________________________________________ __________________
          HS3 Pro Edition 3.0.0.548, NUC i3

          HW: Stargate | NX8e | CAV6.6 | Squeezebox | PCS | WGL 800RF | RFXCOM | Vantage Pro | Green-Eye | Edgeport/8 | Way2Call | Ecobee3 | EtherRain | Ubiquiti

          Comment


            #6
            Hi Mike-

            The debug log is basically what you have provided, thanks a bunch, this is great data.

            It seems that the SetDeviceValueByName call is causing the script to hang. So, that scould call the SetIOEx function within the plugin, which I will take a look at. Also, on the "1/4" names, did a re-import with "update devices" checked fix this? This should really be writing "JDS" to that property no matter what.
            -RJ (HomeSeer Tech)

            Comment


              #7
              Hi Mike-

              I did just notice something peculiar. The stargate will be waiting 30 seconds for an ACK, or a response, to the variable set command. IS there some property in WinEVM that could be causing this variable to become unresponsive? I'm not familiar with WinEVM, but if there is some sort of "Don't log this" feature, then this could be the culprit.
              -RJ (HomeSeer Tech)

              Comment


                #8
                RJ,
                I just reimported the flags and that replaced '1/4' with 'JDS'. Thanks. ...Interesting behavior, though.

                WinEVM has a selection mechanism to choose what to log. I have everything checked at the moment. Also, if I set a variable in an event action I don't see any lag. (That's what I'm doing now that I am not running this script. I just reset the variable to 10 as a device action.)
                Mike____________________________________________________________ __________________
                HS3 Pro Edition 3.0.0.548, NUC i3

                HW: Stargate | NX8e | CAV6.6 | Squeezebox | PCS | WGL 800RF | RFXCOM | Vantage Pro | Green-Eye | Edgeport/8 | Way2Call | Ecobee3 | EtherRain | Ubiquiti

                Comment


                  #9
                  There is a "don't log this" function in WinEVM, but Homeseer sends the command to clear it when it starts up. When the plugin sends the filtering command ##%0a0202ffff, this enables everything to be viewed in WinEVM. I do not know if this affects which items are received by ECHO mode, called by the ##%1d command, since the documentation says that ECHO mode simply causes all actions to be broadcast on the serial port, without mentioning whether it is subject to the filtering command.

                  I assume the problem is happening when people are running WinEVM and Homeseer simultaneously.

                  It is likely possible that WinEVM and the Stargate get out of synch. I recommend turning off all filtering in WinEVM to correspond with the command that Homeseer sends that turns off all filtering.

                  Additionally, they could add a direct script action in Homeseer to send the "##%0a0202ffff" command again if they are having problems. Then they'd know if that's the cure.

                  Tim
                  Last edited by timlacey; December 9, 2006, 11:18 AM. Reason: clarifications

                  Comment


                    #10
                    Hi Guys-

                    I guess I need to be more specific here. What homeseer does is it sets the variable, then waits for an acknowledge on that same set. The timeout there is 30 seconds, the same delay observed with the script. This means that the acknowledge is never received, and thus HomeSeer locks up.

                    I am still looking into this, but thus far have not found anything. I will keep you all posted if anything does come up on this, and for now I would reccomend that you use event functionality instead.
                    -RJ (HomeSeer Tech)

                    Comment

                    Working...
                    X