Event Execution Delay Measurement Script discussion

[fungun]

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

[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 -

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

[fungun]

Here is how it started out -

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

[Wadenut]

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.

[fungun]

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

[Wadenut]

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.

[fungun]

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

0.312 seconds [Delta: 0.156 Min: 0.059 Max: 35.422 @ 7/31/2013 2:11 PM]

But this shows in the log

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.

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

[fungun]

Never mind, I got it.

Tim

[Wadenut]

HS3 version posted.

[fungun]

Anyone seen this?
Just noticed it today.

Thanks,
Tim

[Wadenut]

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.

[fungun]

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

[Wadenut]

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.

[fungun]

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

Thanks,
Tim

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

[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

[Wadenut]

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.

[fungun]

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

Thanks,
Tim