Gateway timer event fixed delay not correct

deancable · September 11, 2020, 5:10pm

Hello,

I used to use Ignition 7.9 and had gateway TIMER events defined as FIXED DELAY on DEDICATED threading to execute every 60 seconds.

The script within the timer event would take anywhere from 10-15 seconds to execute.
THEN, 60 seconds after that the timer would execute again. Just like in the documentation.

However since I have upgraded to Ignition 8.0.13 this is not behaving the same.
I have a “master” inheritable project defined.
I have the gateway timer events defined in it.
I have a “child” project defined that has my windows in it.

NOW when my gateway timer events fire, the execute as follows.

gateway starts.
60 seconds later the timer fires.
My script within the timer executes for 10-15 seconds.
(I verify this with logging.)
50-45 seconds later the timer fires again!

What happened to the FIXED delay that used to be between the END of your script firing INSIDE the timer and the NEXT interval?

thanks

pturmel · September 11, 2020, 5:13pm

How many projects do you have inheriting this? Because that's how many copies of the script will be running. I suspect you are seeing logging from two different projects, not mistiming from one project. Gateway events should never be defined in an inheritable project, only in leaf projects.

deancable · September 11, 2020, 6:01pm

Those are the only 2 PROJECTS in my gateway.
“master” is inheritable.
“child” is inherited from “master” and is not inheritable.

deancable · September 11, 2020, 6:07pm

My gateway TIMER event is defined as follows:

60,000 ms
Delay Type = FIXED DELAY
Threading = DEDICATED

script:
from time import sleep
lSeconds = 10
MES_global.DB.logMessageDirectlyToDB(‘zTestFIXEDdelay’, 'Starting…sleeping for ’ + str(lSeconds))
sleep(lSeconds)
MES_global.DB.logMessageDirectlyToDB(‘zTestFIXEDdelay’, ‘Finished’)

Since my script above takes 10 seconds to “run”.
I would expect there to be 70 seconds between log entries that start with:
'Starting…sleeping for 10

deancable · September 11, 2020, 6:19pm

I changed the threading = SHARED.

same logging as above.
from the END of one execution of the script, there is NOT 60 seconds before
the next one begins.

Kevin.Herron · September 11, 2020, 6:23pm

I’m able to replicate using this script:

from time import sleep

logger = system.util.getLogger('timer_test')

logger.info('starting')

sleep(10)

logger.info('finished')

with these settings:

output:

I [timer_test                    ] [18:21:13]: starting 
I [timer_test                    ] [18:21:23]: finished 
I [timer_test                    ] [18:22:13]: starting 
I [timer_test                    ] [18:22:23]: finished 
I [timer_test                    ] [18:23:13]: starting 
I [timer_test                    ] [18:23:23]: finished

deancable · September 11, 2020, 6:26pm

Thanks Kevin.

Would you happen to have EASY access to an Ignition 7.9 you could check against?

Kevin.Herron · September 11, 2020, 6:53pm

It doesn’t work as you’d expect in 7.9 either. It’s likely never work as expected.

The crazy thing is that this isn’t even some bug in Ignition (I mean technically it is because it’s not behaving like it should), but this is really either a bug in java.util.Timer or its documentation, because this is reproducible on its own in Java.

deancable · September 11, 2020, 8:27pm

Can you suggest a workaround?

So that I get a 60,000ms delay AFTER my script executes…before it executes again?

deancable · September 21, 2020, 8:12pm

Kevin Herron,

Will this be addressed in any upcoming versions?
thank you

Kevin.Herron · September 21, 2020, 8:34pm

Hmm, it probably will be, there’s a ticket but it’s been marked low priority.

mori.luca · November 7, 2020, 12:14pm

Hello everyone,
i faced this same problem and i’d like to say that from my personal point of view,
this shouldn’t be a low priority ticket.

Is there any news on this issue? The documentation is clear about fixed and delay interval.
Is two months i’m struggling wit this, being thinking was something in my code.

Thanks for your time

Kevin.Herron · November 7, 2020, 2:33pm

I’ll note your objection and see if it can be re-reviewed.

Because these timers, while technically behaving incorrectly, have been behaving this way for over a decade and “fixing” them will alter the behavior of many existing projects, the fix may have serious repercussions.

BenKearney · November 7, 2020, 3:34pm

I thought Java’s util.Timer fixed delay schedule implemented a fixed delay from the execution time (i.e. the time the task actually started), rather than from the time the task finished. Variance in how long the task took to execute shouldn’t change when the task is scheduled to run next.

To achieve what is described in the Ignition docs, I think the gateway script would need to manually call schedule() again after every execution for a single schedule rather than trying to set it up to run for an extended period with one call. I don’t know whether this would be fragile or not.

A workaround might be to bind a tag’s value to the system time and write an on change script that does something when the seconds == 0.

Edit: Hey I was reading that!

Kevin.Herron · November 7, 2020, 3:44pm

Yes, that appears to be the case, but that is hardly distinguishable from fixed rate execution.

I ninja-deleted my original response because I misread yours. It was just a code sample showing that fixed delay execution with java.util.Timer is broken entirely independent of Ignition.

BenKearney · November 7, 2020, 3:47pm

Yeah it's basically the same thing to an Ignition user. I think it still achieves one of the benefits from the Ignition docs:

This is the safest option since it prevents a script from mistakenly running continuously because it takes longer to execute the script than the delay.

But this bit isn't accurate

This means that the script's rate will actually be the delay plus the amount of time it takes to execute the script.

The difference probably isn't relevant to an Ignition user, but technically you did implement a fixed delay script - just defined it differently. Safest thing might be to add a third option and clarify what a fixed delay script is. Fixed Sleep or something similar.

Kevin.Herron · November 7, 2020, 3:48pm

Fixed delay is defined and works as expected with ScheduledExecutorService::scheduledWithFixedDelay, which is what we’d probably use instead.

https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/util/concurrent/ScheduledExecutorService.html#scheduleWithFixedDelay(java.lang.Runnable,long,long,java.util.concurrent.TimeUnit)

edit: I’m having a rough morning apparently.

BenKearney · November 7, 2020, 3:51pm

Ah, the old “define fixed-delay two different ways in your documentation” trick. Java you rascal.

Kevin.Herron · November 7, 2020, 3:51pm

Even the docs for java.util.Timer indicate it should behave how we want though:

In fixed-delay execution, each execution is scheduled relative to the actual execution time of the previous execution.

https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/util/Timer.html#schedule(java.util.TimerTask,long,long)

How can you interpret that in a way that resembles fixed rate instead?

BenKearney · November 7, 2020, 3:52pm

In fixed-delay execution, each execution is scheduled relative to the actual execution time of the previous execution.

Here they're using 'execution time' to mean the time that the function begins executing, not the time that it takes to execute. Bit ambiguous.