To the Automic DeLorean! or: can someone please explain this ...?

[Carsten Schmitz]

Hi.

We have a small SCRI that essentially just says "Hello World!".

My management wants near real time runtime graphs for that script. So I made an SQL statement to compute the difference between AH.TIMESTAMP1 and AH.TIMESTAMP2. The first is activation, and the second is the actual launch of processing, right?

This is when I noticed something odd.

Here is a simplified version of the statement:

selectAH_TIMESTAMP1,
AH_TIMESTAMP2,
round((AH_TIMESTAMP2 - AH_TIMESTAMP1) * 24 * 60 * 60) as seconds_diff
from AH,dual
where AH_OH_IDNR in (select OH_IDNR from GFD_IS_UC4_O_01.OH where OH_NAME = 'SCRI.DC1.ENGINE_AVAILABILITY_CHECK');

and here is an excerpt of it's output:

06-12-19 15:02:00|06-12-19 15:02:00| 0
06-12-19 15:03:00|06-12-19 15:03:01| 1
06-12-19 15:04:00|06-12-19 15:04:00| 0
06-12-19 15:05:00|06-12-19 15:05:01| 1
06-12-19 15:06:01|06-12-19 15:06:01| 0
06-12-19 15:07:00|06-12-19 15:07:00| 0
06-12-19 15:08:00|06-12-19 15:08:00| 0
06-12-19 15:09:00|06-12-19 15:09:00| 0
06-12-19 15:10:00|06-12-19 15:10:00| 0
06-12-19 15:11:00|06-12-19 15:11:00| 0
06-12-19 15:12:00|06-12-19 15:12:00| 0
06-12-19 15:13:00|06-12-19 15:13:00| 0
06-12-19 15:14:00|06-12-19 15:14:00| 0
06-12-19 15:15:01|06-12-19 15:15:01| 0
06-12-19 15:16:00|06-12-19 15:16:01| 1
06-12-19 15:17:20|06-12-19 15:17:19| -1
06-12-19 15:18:20|06-12-19 15:18:19| -1
06-12-19 15:19:00|06-12-19 15:19:00| 0
06-12-19 15:20:00|06-12-19 15:20:01| 1
06-12-19 15:21:20|06-12-19 15:21:20| 0
06-12-19 15:21:59|06-12-19 15:21:59| 0
06-12-19 15:23:00|06-12-19 15:22:59| -1
06-12-19 15:23:59|06-12-19 15:24:00| 1
06-12-19 15:25:00|06-12-19 15:24:59| -1
06-12-19 15:26:20|06-12-19 15:26:19| -1
06-12-19 15:27:20|06-12-19 15:27:20| 0
06-12-19 15:28:00|06-12-19 15:28:00| 0
06-12-19 15:29:01|06-12-19 15:29:01| 0
06-12-19 15:30:00|06-12-19 15:30:01| 1

I understand that it sometimes takes a second.

I understand that it sometimes takes 0 seconds, due to rounding down.

I don't understand how TIMESTAMP2 can ever be LESS than TIMESTAMP1 ???

[Pete Wirfs]

Interesting exercise.

SCRI objects don't really have a run-time in the common sense.   
To observe this behavior, I ran this in a SCRI object;

:print "starting"
:wait 5
:print "ending"​

The two PRINT messages were printed 5 seconds apart.  But UC4 tells me it ran in 0000 seconds.
This is because script execution is considered to occur *before* the task starts running, and will not count script time in the task run time.

So, back to your observation of negative time results, my hypothesis is that the UC4 service that records activation time and the UC4 service that records start time are probably different services, and your results tell me they are off by a fraction of a second.   I'm only guessing here, but maybe the PWP logs the activation time, and hands it off to another WP?

------------------------------
Pete
------------------------------

[Michael Pirson]

Using generate at run-time will cause the actual run-time to show for the SCRI objects. Maybe that pesky 'feature' could be contributing to this issue?

Regards,

Michael

[Pete Wirfs]

Good observation.  I ran my script with "Generate task at runtime" selected and now Uc4 tells me it took 5 seconds to execute.

In Carsten's experiment, if it is set to "Generate Task at activation time" then he is trying to capture the time that it took to do nothing.

@Carsten Schmitz What do you get when you turn on the "Generate task at runtime" option under Attributes?​

------------------------------
Pete
------------------------------

[Carsten Schmitz]

Hi Pete,

thanks​ for weighin in!

Yeah, we purposefully chose a SCRI, as oposed to a JOBS or something else. Reason being, that thing originated from the demand for a "heartbeat" monitoring of the engine after we had stuck processes that looked alive, but didn't do anything.*) While we also monitor agents by running periodic JOBS, for the central server we wanted the object that is the least dependend on anything else, such as agents. SCRI fit the bill.

While there are two engine servers involved, they run ntpd, and according to "date --rfc-3339=ns" currently are about 1/100th of a second apart - way too (edit) much little for these timings to be explained by a rounding error from this.

I have now changed the thing to "Generate at runtime" and will report when I have a day of results or so (so ... erm ... probably on Monday :)



*) incidentially, this still happens, I have a ticket open at Automic for another incarnation of stuck processes).

------------------------------
I will not respond to PM asking for help unless there's an actual reason to keep the discussion off of the public forums.
------------------------------

[Tim Quakulinsky]

A few years ago we had jobs with negative runtimes (just 1 or 2 seconds). I asked the Product Management to improve this feature ("started today, ended yesterday") which was unfortunately rejected. From my point of view this would be a real competitive advantage ;-)

Best regards,
Tim

------------------------------
Automation Evangelist
Fiducia & GAD IT AG
---
Mitglied des deutschsprachigen Automic-Anwendervereins FOKUS e.V.
Member of the German speaking Automic user association FOKUS e.V.
------------------------------

[Carsten Schmitz]

Hehe :)

I've heard of time compression in software before, but this has potential. Meet CALE.RELATIVE - the faster it runs, the more hours beyond a mere twentyfour it adds to your day ;)

Also, as promised, I tried this with "generate at runtime". Doesn't change anything, this also generates the occasional SCRI that has -1 seconds diff.

Currently contemplating if opening a ticket makes any sense ...?

[Marcin Uracz]

Some time ago I was struggling with a similar problem in which an automatic  file event was processed (according to the activation time in Automic) seconds before a dataset was created on the MVS side :) In the end we did not reach any constructive conclusion. Other then that Automic does not guarantee  precision up to a second. This was with V12.1.

------------------------------
Automic Consultant
------------------------------