Announcement

Collapse
No announcement yet.

Event Execution Delay Measurement Script discussion

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

  • fungun
    replied
    It's almost like the device string wasn't getting updated, just added to it.

    Thanks,
    Tim

    Leave a comment:


  • Wadenut
    replied
    It didn't cause your problem but I'd change LogWrngThrshld to something more than 0. I don't remember whether or not a setting of 0 turns off the warning. although it probably should next time I do anything with the script. Somewhere between 0.5 and 1.5 wouldn't be unreasonable. The next setting is the number of samples outside this limit before you'll get a warning.

    Leave a comment:


  • fungun
    replied
    Here is some logging before and after my restart.
    I will also attach my ini file for you.

    Thanks,
    Tim

    Code:
    2/16/2015 3:31:00 PM ~!~EventDelay~!~Current delay: 0.064 seconds [Delta: 0 Min: 0.064 Max: 0.705 @ 2/16/2015 3:27 PM] Last Event: EventDelayMsrmnt.  Scripts running: Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb,Event Delay Measurement.vb
    2/16/2015 3:31:09 PM ~!~Event~!~Event Trigger "MaxUptime"
    
    RESTART
    
    2/16/2015 3:57:02 PM ~!~EventDelay~!~Current delay: 1.314 seconds [Delta: 0.953 Min: 0.08 Max: 1.314 @ 2/16/2015 3:57 PM] Last Event: EventDelayMsrmnt.  Scripts running: Jon00RCCNM_Monitor.vben,Event Delay Measurement.vb
    
    2/16/2015 4:00:00 PM ~!~EventDelay~!~Current delay: 0.267 seconds [Delta: 0.109 Min: 0.08 Max: 1.314 @ 2/16/2015 3:57 PM] Last Event: EventDelayMsrmnt.  Scripts running: Event Delay Measurement.vb,2StockQuotesTicker.txt

    Code:
    [Configuration]
    TrackingDevice = S35
    GraphingDevice = 
    Jon00GraphNum  = 
    
    LogWrngThrshld = 0
    LogWrngSamples = 2
    SpkWrngThrshld = 10
    SpkWrngSamples = 5
    SpeakMessage   = Homeseer event execution is seriously delayed. Immediate intervention may be required.
    RunScptThrshld = 0
    RunScptSamples = 10
    ScriptToRun    = 
    RebootThrshold = 0
    RebootSamples  = 1
    UseTextInGraph = True
    IncludeDelta   = True
    IncludeMinMax  = True
    IncludeTOD     = True
    IncludeEvents  = True
    IncludeScripts = True
    
    [Data]
    LastRunTime =2/16/2015 4:29:00 PM
    LastDelay =0.095
    MinDelay  =0.08
    MaxDelay  =0.314
    MaxDelayTOD =2/16/2015 4:21 PM
    ExSamples =0

    Leave a comment:


  • Wadenut
    replied
    Originally posted by fungun View Post
    The delays vary, usually under 1 second. (I was tasking it for testing)
    Once I noticed the repeating same script running, I watched it for over a hour.
    The delays varied but not the "Scripts running' part of the device string.
    I restarted HS and all is good now. It reports other events / scripts that are running instead of just itself running repeatedly.

    Tim
    As I recall, there's a setting in the INI which determines the threshold where reporting will start. Below that, it just runs quietly. Here, I normally see delays of about 60ms which would just be the time it takes for HS to trigger the event and start the script. The first thing it does is take a snap of the current time. After that, it reads the INI, does the math, sets the device string, reports and exits.

    Leave a comment:


  • fungun
    replied
    The delays vary, usually under 1 second. (I was tasking it for testing)
    Once I noticed the repeating same script running, I watched it for over a hour.
    The delays varied but not the "Scripts running' part of the device string.
    I restarted HS and all is good now. It reports other events / scripts that are running instead of just itself running repeatedly.

    Tim

    Leave a comment:


  • Wadenut
    replied
    Originally posted by fungun View Post
    Anyone seen this?
    Just noticed it today.

    Thanks,
    Tim
    Looks like you've got some delay there. The list is a list of running scripts, which in this case means you have many copies running for some reason, and likely causing the delay in the first place.
    In the event, you ought to have "allow only one to run" (not sure of the exact wording there; it's under advanced in the Action section). There's nothing in the script that would cause it to hang that I'm even remotely aware of... ie. no loops of any sort. It's actually quite linear.... In, measure, report, out.

    Leave a comment:


  • fungun
    replied
    Anyone seen this?
    Just noticed it today.

    Thanks,
    Tim
    Attached Files

    Leave a comment:


  • Wadenut
    replied
    HS3 version posted.

    Leave a comment:


  • fungun
    replied
    Never mind, I got it.

    Tim

    Leave a comment:


  • fungun
    replied
    I would like to change what the device string shows.
    As it is, this is what it shows in the device string.

    Code:
    0.312 seconds [Delta: 0.156 Min: 0.059 Max: 35.422 @ 7/31/2013 2:11 PM]
    But this shows in the log

    Code:
    Current delay: 0.203 seconds [Delta: 0.094 Min: 0.059 Max: 35.422 @ 7/31/2013 2:11 PM] Last Event: UpdateWthrXmlCond.  Scripts running: Event Delay Measurement.vb
    I would like the device string to show what shows up in the log.
    It looks like this is the right section, but I am not 100% sure.

    Code:
    LogString = "Current delay: " & DVString 
        If UseEvents Then LogString = LogString + " Last Event: " + LastEvent 
        If UseScripts Then LogString = LogString + ".  Scripts running: " + RunningScripts 
        If TrackDV <> "" Then
            hs.SetDeviceString(TrackDV,"<font color=" & DVColor & ">" & DVString & "</font>")
            hs.SetDeviceValue(TrackDV,CInt(DelayTime * 1000))
        End If
    Thanks,
    Tim

    Leave a comment:


  • Wadenut
    replied
    Good.
    Nonetheless, 1.12.2 is identical in every way to 1.12.1 except it adds a completely optional parameter to the "Configuration" section of the INI. If present, and set to TRUE, "DEBUG" will produce a single informational log entry on each execution of the script.
    If you DO feel the need to upgrade from 1.12.1, don't replace your INI file. Just add the Debug parameter if you wish.

    Just for the record, I've been using the same copy as has been uploaded, since last August, without issues on two installations of HS. Any time a delay has been reported, it's been real.

    Leave a comment:


  • fungun
    replied
    I changed the event-trigger every 1 minute-referance to the hour-running the script with ("Main","1").

    Now I am getting 0.079 as a reading
    Much better!
    Thank you,
    Tim

    Leave a comment:


  • Wadenut
    replied
    Post your config file and a screen shot of your event schedule, trigger and action.

    From your log:
    I see the event sometimes running every minute, not every two. This will cause the calculation to be incorrect if you specify a different parameter in the event action. The parameter absolutely must match the trigger frequency.
    I see too the event is never being triggered on the minute (Seconds = 0). This is essential, otherwise you will get delays reported as it's exactly that time difference the script is measuring.


    And again, there's no reason not to run this on a one minute schedule at least until you've gotten things working properly.

    The speed of a machine has little to do with how Homeseer behaves.

    I was wrong about Priority and Allow one inscance to run. These should be unchecked. However, you do need to check "Reference to the Hour" under the trigger tab.
    I'm adding a debug routine to provide a little more information to the log in these cases. Should be ready shortly.
    Last edited by Wadenut; May 27th, 2013, 11:53 AM.

    Leave a comment:


  • fungun
    replied
    Here is how it started out -

    Code:
    5/26/2013 11:05:05 PM ~!~Event~!~Running script in background: Event Delay Measurement.vb("Main","2")
    5/26/2013 11:05:05 PM ~!~Warning~!~Events delayed: Current delay: 43865.375 seconds [Delta: 43865.297 Min: 0.062 Max: 43865.375 @ 5/26/2013 11:05 PM] Last Event: EventDelayMsrmnt.  Scripts running: Event Delay Measurement.vb
    5/26/2013 11:05:22 PM ~!~Device Control~!~Device:  SystemInfo EventDelayTime (S35) ON
    5/26/2013 11:05:26 PM ~!~Device Control~!~Device:  SystemInfo EventDelayTime (S35) OFF
    5/26/2013 11:06:21 PM ~!~Event~!~Event Trigger "EventDelayMsrmnt"
    5/26/2013 11:06:21 PM ~!~Event~!~Running script in background: Event Delay Measurement.vb("Main","2")
    5/26/2013 11:07:05 PM ~!~Event~!~Event Trigger "EventDelayMsrmnt"
    5/26/2013 11:07:05 PM ~!~Event~!~Running script in background: Event Delay Measurement.vb("Main","2")
    5/26/2013 11:07:05 PM ~!~Warning~!~Events delayed: Current delay: 65.062 seconds [Delta: 103.125 Min: 0 Max: 43865.375 @ 5/26/2013 11:05 PM] Last Event: EventDelayMsrmnt.  Scripts running: Event Delay Measurement.vb
    5/26/2013 11:09:05 PM ~!~Event~!~Event Trigger "EventDelayMsrmnt"
    5/26/2013 11:09:05 PM ~!~Event~!~Running script in background: Event Delay Measurement.vb("Main","2")
    5/26/2013 11:09:05 PM ~!~Warning~!~Events delayed: Current delay: 65.062 seconds [Delta: 0 Min: 0 Max: 43865.375 @ 5/26/2013 11:05 PM] Last Event: EventDelayMsrmnt.  Scripts running: Event Delay Measurement.vb
    5/26/2013 11:09:57 PM ~!~Event~!~Event Trigger "WeatherWarnings"
    Thanks,
    Tim

    Leave a comment:


  • fungun
    replied
    Yes the event is recurring every 2 minutes and the script para is "main","2".
    On the old PC with HS running now, it is usually .06 to .09 and sometimes up to 2.0 or so.
    I can't believe HS on this larger, faster, newer PC would be in the 53 range.
    It is so much faster in executing scripts, turning lights on/off, picking up motion detectors ect ect.
    That's the main reason I am switching over to this PC. Even the status page is lighting fast.

    Thanks,
    Tim

    ps ini file

    Code:
    [Configuration]
    TrackingDevice = S35
    GraphingDevice = 
    Jon00GraphNum  = 
    
    LogWrngThrshld = 0
    LogWrngSamples = 2
    SpkWrngThrshld = 10
    SpkWrngSamples = 5
    SpeakMessage   = Homeseer event execution is seriously delayed. Immediate intervention may be required.
    RunScptThrshld = 0
    RunScptSamples = 10
    ScriptToRun    = Event Delay Actions.vb
    RebootThrshold = 0
    RebootSamples  = 1
    UseTextInGraph = True
    IncludeDelta   = True
    IncludeMinMax  = True
    IncludeTOD     = True
    IncludeEvents  = True
    IncludeScripts = True
    
    [Data]
    LastRunTime =5/27/2013 9:32:53 AM
    LastDelay =53.046
    MinDelay  =21.265
    MaxDelay  =53.109
    MaxDelayTOD =5/27/2013 12:16 AM
    ExSamples =283

    from the old PC -
    Code:
    5/27/2013 9:34:15 AM ~!~EventDelay~!~Current delay: 0.283 seconds [Delta: -0.469 Min: 0 Max: 17.359 @ 5/18/2013 7:00 AM] Last Event: EventDelayMeasurment.  Scripts running: Event Delay Measurement.vb

    Leave a comment:

Working...
X