Problematic code in Delay>checkDelayedTasks

rolloverTime := PreviousClockValue + InterruptPeriod.

"Adjust the resumption time for every process that
was suspended before the rollover. If the resumption time
was after the previous clock value but before the projected
rollover time then adjust the resumption time to be exactly
the projected rollover time (which is zero after the rollover)."
self delayedTasks do: [:task | | t |
(t := task resumptionTime) >= PreviousClockValue
ifTrue: [task resumptionTime: ((t - rolloverTime) max: 0)]]]].

timeAdjustment := PreviousClockValue - currentTime.
self delayedTasks do: [:task | task resumptionTime: (task resumptionTime - timeAdjustment)].

Note that I don't worry about the redumptionTime being beyond the PreviousClockValue, they all should be and it won't hurt if they aren't.  Also,  I don't worry about the redumptionTime going negative, the delay will still fire.

On Thursday, August 2, 2012 5:22:00 PM UTC-4, Louis LaBrunda wrote:

Note that I don't worry about the redumptionTime being beyond the PreviousClockValue, they all should be and it won't hurt if they aren't.  Also,  I don't worry about the redumptionTime going negative, the delay will still fire.

If I remember correctly, it was actually an incident I was involved in  that resulted in this code being added.  Our application, running on an AIX box, was actually being affected by time apparently moving backward.  Delays were being expired prematurely, impacting our production line.  In actual fact, the computer's clock was running fast, and kept being reset by a Kerberos monitor that was watching a cluster of computers.

Which is not to say that there are no problems with the implementation, but there are reasons for it being the way it is.

Tom

Your AIX experience is interesting, my experience is only with Windows.

((currentTime between: PreviousClockValue and: PreviousClockValue + 500) ifFalse: [

   timeAdjustment := PreviousClockValue - currentTime + InterruptPeriod.

   self delayedTasks do: [:task | task resumptionTime: (task resumptionTime - timeAdjustment)].

].

On Friday, August 3, 2012 10:38:36 AM UTC-4, Louis LaBrunda wrote:

 

Your AIX experience is interesting, my experience is only with Windows.

It was new for us, too.  We had just converted over to some new hardware, and before we found out about the time being reset from an external source, the only obvious explanation was that the hardware had become so fast that it was exceeding the speed of light.  :{)  Just to make it interesting, we were still running VA 4.5 at the time, although the rest of the world had moved on to 6.0 by then.

I'll try to find my old notes on the problem this weekend to see if they shed any light on the thinking process that led to the current solution.

Tom

I've really got to get a VA environment set up at home again!  I did check my old notes, and discovered that we wrestled with this problem in mid-November of 2001.  The IBM team working on it found that it also affected Java applications, which wasn't a major issue for us at the time.  Not a lot of other details...

Tom

As I mentioned originally, the time changes were a Kerberos artifact.  When using Kerberos tickets to provide authentication between machines in a cluster, it's vital that time be kept consistent between machines so that tickets don't expire unexpectedly.   Stand-alone Windows and Unix boxes don't have such a stringent requirement on their timekeeping, so they can get by with hitting an NTP server on a regular basis.

The clock running fast was the cause of the Delays being expired prematurely (not the backward jumps) and the current code doesn't test for this (which it can't) or even test for jumping ahead.

 The current code has added a new problem by ignoring small jumps backward (up to 5 minutes), which then causes delays to expire late by the amount of time of the up to 5 minute backward jump.

This can be tested by checking to see if currentTime is between PreviousClockValue and PreviousClockValue + 500.

((currentTime between: PreviousClockValue and: PreviousClockValue + 500) ifFalse: [

   timeAdjustment := PreviousClockValue - currentTime + InterruptPeriod.

   self delayedTasks do: [:task | task resumptionTime: (task resumptionTime - timeAdjustment)].

On Monday, August 6, 2012 12:29:50 PM UTC-4, Louis LaBrunda wrote:

The clock running fast was the cause of the Delays being expired prematurely (not the backward jumps) and the current code doesn't test for this (which it can't) or even test for jumping ahead.

Actually, Delays were being expired prematurely because of the backward jumps.  As originally implemented, the delay timer was seeing that the new time was less than the old time, and therefore assuming clock rollover.  Based on that assumption, it was decided that there was a major shift in time forward, and any Delays should be expired.

timeAdjustment := PreviousClockValue - currentTime + InterruptPeriod.

The current code has added a new problem by ignoring small jumps backward (up to 5 minutes), which then causes delays to expire late by the amount of time of the up to 5 minute backward jump.

In our case, at least, a timer expiring a little later is less problematic than one expiring too soon.  We use delays to control timeouts on things such as torque gun controls (we build cars here), and if the delay expires too soon, the assembly line worker does not have enough time to complete his or her task on the vehicle. 

This can be tested by checking to see if currentTime is between PreviousClockValue and PreviousClockValue + 500.

((currentTime between: PreviousClockValue and: PreviousClockValue + 500) ifFalse: [

   timeAdjustment := PreviousClockValue - currentTime + InterruptPeriod.

   self delayedTasks do: [:task | task resumptionTime: (task resumptionTime - timeAdjustment)].

 
I don't actually see how your code is materially different from what is already there, except for tighter values on the test range.

Tom

Lou, I'm still not seeing a significant difference between what you've done and what's already implemented except for using 500 ms instead of 30000.

"currentTime between: PreviousClockValue and: PreviousClockValue + 500" is equivalent to "PreviousClockValue - currentTime < 500", so the same delays would be affected.  The only other change is that you're touching all delays rather than just those that should have expired since the last check.

Tom

timeAdjustment := PreviousClockValue - currentTime + InterruptPeriod.

rolloverTime := PreviousClockValue + InterruptPeriod.

If you have the time (puns are flying all over this post) try some numbers.  I will try to post some numbers to show the various possibilities.

tests

add: #('Rollover' 4294967200 10 4294967400);

add: #('Jump Back' 4294967290 4294967200 4294967395);

add: #('Jump Forward' 4294966100 42949676000 4294966205).

Transcript cr.

tests do: [:t | | pcv ct adj delayTo |

pcv := t second.

ct := t third.

adj := pcv - ct + 100.

delayTo := t fourth.

Transcript show: t first; show: ' - PreviousClockValue>'; show: pcv printString;

show: ', CurrentTime>'; show: ct printString; show: ', Adjustment>'; show: adj printString;

show: ', delayToWas>'; show: delayTo printString; show: ', delayToIs>'; show: (delayTo - adj) printString; cr.

].

Rollover - PreviousClockValue>4294967200, CurrentTime>10, Adjustment>4294967290, delayToWas>4294967400, delayToIs>110
Jump Back - PreviousClockValue>4294967290, CurrentTime>4294967200, Adjustment>190, delayToWas>4294967395, delayToIs>4294967205
Jump Forward - PreviousClockValue>4294966100, CurrentTime>42949676000, Adjustment>-38654709800, delayToWas>4294966205, delayToIs>42949676005

On Tuesday, August 7, 2012 2:20:11 PM UTC-4, Louis LaBrunda wrote:

If you have the time (puns are flying all over this post) try some numbers.  I will try to post some numbers to show the various possibilities.

By all means, bring on some numbers.   However, I'm worried that we may have headed off down some rabbit hole that may or may not have anything to do with the problem you're really having.  Could we get some more details on that without giving away any trade secrets?

Here's how I interpret the code as it currently exists:

If the current timestamp is greater than or equal to the previous timestamp, then time is progressing more or less as we expect.
If it isn't, let's see if the time has moved back more than our tolerated amount (MillisecondClockValueEpsilon).
If it hasn't, we'll just pretend that the current timetamp is the same as the previous timestamp.
Otherwise, we'll reset the resumption times of all the delays that should have resumption timestamps after the previous timestamp to be some time in the period after the previous timestamp plus the timer resolution (100ms).

Once we've done all that, let's see if anybody's resumption time is less than the current time, and resume them.

The only way I could see you having a problem with this is if the MillisecondClockValueEpsilon is larger than you can tolerate.

However, bring on some numbers, and let's see.

Tom

Run this code in a workspace, play with the numbers if you like.

My latest theory (I'm trying to think of how to test it) is that a delay ends and its process is set to ready but NOT added back to its priority queue.  In the case of the program where things went back to normal, maybe the process got put back into the queue.  The code at the end of Delay>checkDelayedTasks that sets processes ready and puts them back in their queue is not wrapped in a critical block and interrupts are not disabled, so maybe with some bad timing, the process may not get put back in its priority queue.

On Tuesday, August 7, 2012 4:14:26 PM UTC-4, Louis LaBrunda wrote:

Run this code in a workspace, play with the numbers if you like.

 I'm guessing these numbers are actual observations you've gathered from your testing.  I assume that you had some printStrings embedded in the #checkDelayedTasks method in order to gather them.

Based on that, I'm not sure I seen the problem. 

My latest theory (I'm trying to think of how to test it) is that a delay ends and its process is set to ready but NOT added back to its priority queue.  In the case of the program where things went back to normal, maybe the process got put back into the queue.  The code at the end of Delay>checkDelayedTasks that sets processes ready and puts them back in their queue is not wrapped in a critical block and interrupts are not disabled, so maybe with some bad timing, the process may not get put back in its priority queue.

While I'm loathe to suggest a major architectural change, have you looked at SstCron and SstCronEntry as a way to manage your pool of tasks?  Your problems may not go away, but a larger chunk of the issue is now squarely back in Instantiations code, and you're in a much better position to toss the problem to them.

Tom