strange time / delay problems on pharo-contribution-linux64-4.ci.inria.fr
There seems to be a problem on pharo-contribution-linux64-4.ci.inria.fr AFAICT. I can reproduce the following to phenomena: 1. '(Delay forSeconds: 10) waitâ does not wait. 2. âDateAndTime nowâ does not change for long intervals. For instance, the following code: (FileSystem disk workingDirectory / 'foo.log') writeStreamDo: [ :stream | stream nextPutAll: DateAndTime now asString;crlf. stream nextPutAll: ([(Delay forSeconds: 10) wait] timeToRun / 1000) asString; crlf. stream nextPutAll: DateAndTime now asString ]. produces this output: 2014-03-04T21:32:21.396669+01:00 0:00:00:00 2014-03-04T21:32:21.396669+01:00 Too me (and my untrained eye) this looks like a system clock problem. Could somebode take a look at the server in question? Cheers, Max
Hey Max, Great catch, I saw some weird stuff too, and we had this conversation :
may be just = and time does not pass fast enough/
On 03 Mar 2014, at 22:22, no-reply@ci.inria.fr wrote:
https://ci.inria.fr/pharo/job/Pharo-3.0-Update-Step-2.1-Validation-A-L/label...
1 regressions found. KernelTests.Chronology.DateAndTimeTest.testMonotonicity
How the hell can this fail ? The clock moving backwards ??
testMonotonicity
| t1 t2 t3 t4 | t1 := DateAndTime now. t2 := DateAndTime now. (Delay forMilliseconds: 1000) wait. t3 := DateAndTime now. t4 := DateAndTime now.
self assert: (t1 <= t2); assert: (t2 < t3); assert: (t3 <= t4).
So you proofed Stef's assumption of time standing still ;-) But there were earlier problems as well. Thx ! On 04 Mar 2014, at 21:43, Max Leske <maxleske@gmail.com> wrote:
There seems to be a problem on pharo-contribution-linux64-4.ci.inria.fr AFAICT. I can reproduce the following to phenomena:
1. '(Delay forSeconds: 10) waitâ does not wait. 2. âDateAndTime nowâ does not change for long intervals.
For instance, the following code:
(FileSystem disk workingDirectory / 'foo.log') writeStreamDo: [ :stream | stream nextPutAll: DateAndTime now asString;crlf. stream nextPutAll: ([(Delay forSeconds: 10) wait] timeToRun / 1000) asString; crlf. stream nextPutAll: DateAndTime now asString ].
produces this output:
2014-03-04T21:32:21.396669+01:00 0:00:00:00 2014-03-04T21:32:21.396669+01:00
Too me (and my untrained eye) this looks like a system clock problem. Could somebode take a look at the server in question?
Cheers, Max
Phew! I already thought I was crazy :) In that case here are two more tidbits: - I tried to log âDateAndTime nowâ in a different test simultaneously. The timestamp produced there was different, suggesting that the clock does move from time to time. - FileSystemTests>>testEntryAt exhibits that problem. But the tests run on the main Pharo machines are fine (thatâs why I thought it might be the system clock). - the same test only fails in the Pharo3 image, not in Pharo2, but both use the stable PharoVM for building. Hope that helps. On 04.03.2014, at 22:10, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hey Max,
Great catch, I saw some weird stuff too, and we had this conversation :
may be just = and time does not pass fast enough/
On 03 Mar 2014, at 22:22, no-reply@ci.inria.fr wrote:
https://ci.inria.fr/pharo/job/Pharo-3.0-Update-Step-2.1-Validation-A-L/label...
1 regressions found. KernelTests.Chronology.DateAndTimeTest.testMonotonicity
How the hell can this fail ? The clock moving backwards ??
testMonotonicity
| t1 t2 t3 t4 | t1 := DateAndTime now. t2 := DateAndTime now. (Delay forMilliseconds: 1000) wait. t3 := DateAndTime now. t4 := DateAndTime now.
self assert: (t1 <= t2); assert: (t2 < t3); assert: (t3 <= t4).
So you proofed Stef's assumption of time standing still ;-)
But there were earlier problems as well.
Thx !
On 04 Mar 2014, at 21:43, Max Leske <maxleske@gmail.com> wrote:
There seems to be a problem on pharo-contribution-linux64-4.ci.inria.fr AFAICT. I can reproduce the following to phenomena:
1. '(Delay forSeconds: 10) waitâ does not wait. 2. âDateAndTime nowâ does not change for long intervals.
For instance, the following code:
(FileSystem disk workingDirectory / 'foo.log') writeStreamDo: [ :stream | stream nextPutAll: DateAndTime now asString;crlf. stream nextPutAll: ([(Delay forSeconds: 10) wait] timeToRun / 1000) asString; crlf. stream nextPutAll: DateAndTime now asString ].
produces this output:
2014-03-04T21:32:21.396669+01:00 0:00:00:00 2014-03-04T21:32:21.396669+01:00
Too me (and my untrained eye) this looks like a system clock problem. Could somebode take a look at the server in question?
Cheers, Max
On 04 Mar 2014, at 22:34, Max Leske <maxleske@gmail.com> wrote:
Phew! I already thought I was crazy :)
In that case here are two more tidbits: - I tried to log âDateAndTime nowâ in a different test simultaneously. The timestamp produced there was different, suggesting that the clock does move from time to time. - FileSystemTests>>testEntryAt exhibits that problem. But the tests run on the main Pharo machines are fine (thatâs why I thought it might be the system clock). - the same test only fails in the Pharo3 image, not in Pharo2, but both use the stable PharoVM for building.
There is a big difference in how DateAndTime class>>#now works in 2.0 vs 3.0. The former uses #millisecondClockValue while the latter uses #microsecondClockValue. Furthermore 2.0 does all kind of crazy stuff with a loop and Delays to try to improve the accuracy, we threw all that out. Yeah, I guess the clock is just being updated slowly, maybe under heavy load. The question is where that happens. I think in the virtualised OS.
Hope that helps.
On 04.03.2014, at 22:10, Sven Van Caekenberghe <sven@stfx.eu> wrote:
Hey Max,
Great catch, I saw some weird stuff too, and we had this conversation :
may be just = and time does not pass fast enough/
On 03 Mar 2014, at 22:22, no-reply@ci.inria.fr wrote:
https://ci.inria.fr/pharo/job/Pharo-3.0-Update-Step-2.1-Validation-A-L/label...
1 regressions found. KernelTests.Chronology.DateAndTimeTest.testMonotonicity
How the hell can this fail ? The clock moving backwards ??
testMonotonicity
| t1 t2 t3 t4 | t1 := DateAndTime now. t2 := DateAndTime now. (Delay forMilliseconds: 1000) wait. t3 := DateAndTime now. t4 := DateAndTime now.
self assert: (t1 <= t2); assert: (t2 < t3); assert: (t3 <= t4).
So you proofed Stef's assumption of time standing still ;-)
But there were earlier problems as well.
Thx !
On 04 Mar 2014, at 21:43, Max Leske <maxleske@gmail.com> wrote:
There seems to be a problem on pharo-contribution-linux64-4.ci.inria.fr AFAICT. I can reproduce the following to phenomena:
1. '(Delay forSeconds: 10) waitâ does not wait. 2. âDateAndTime nowâ does not change for long intervals.
For instance, the following code:
(FileSystem disk workingDirectory / 'foo.log') writeStreamDo: [ :stream | stream nextPutAll: DateAndTime now asString;crlf. stream nextPutAll: ([(Delay forSeconds: 10) wait] timeToRun / 1000) asString; crlf. stream nextPutAll: DateAndTime now asString ].
produces this output:
2014-03-04T21:32:21.396669+01:00 0:00:00:00 2014-03-04T21:32:21.396669+01:00
Too me (and my untrained eye) this looks like a system clock problem. Could somebode take a look at the server in question?
Cheers, Max
On Tue, Mar 4, 2014 at 2:37 PM, Sven Van Caekenberghe <sven@stfx.eu> wrote: > > On 04 Mar 2014, at 22:34, Max Leske <maxleske@gmail.com> wrote: > > > Phew! I already thought I was crazy :) > > > > In that case here are two more tidbits: > > - I tried to log 'DateAndTime now' in a different test simultaneously. > The timestamp produced there was different, suggesting that the clock does > move from time to time. > > - FileSystemTests>>testEntryAt exhibits that problem. But the tests run > on the main Pharo machines are fine (that's why I thought it might be the > system clock). > > - the same test only fails in the Pharo3 image, not in Pharo2, but both > use the stable PharoVM for building. > > There is a big difference in how DateAndTime class>>#now works in 2.0 vs > 3.0. The former uses #millisecondClockValue while the latter uses > #microsecondClockValue. Furthermore 2.0 does all kind of crazy stuff with a > loop and Delays to try to improve the accuracy, we threw all that out. > > Yeah, I guess the clock is just being updated slowly, maybe under heavy > load. The question is where that happens. I think in the virtualised OS. > That makes sense. In the VM the microsecond clock is updated on every heartbeat and the heartbeat should be running at about 500Hz. Can anyone with hardware confirm that in 3.0 the time on linux does indeed increase at about 500Hz? Note that even in 2.0 the time is being derived from the same basis. In Cog, the effective time basis is the 64-bit microsecond clock maintained by the heartbeat and even the secondClock and millisecondClock are derived from this. So its still confusing why there should be such a difference between 2.0 and 3.0. > > > Hope that helps. > > > > On 04.03.2014, at 22:10, Sven Van Caekenberghe <sven@stfx.eu> wrote: > > > >> Hey Max, > >> > >> Great catch, I saw some weird stuff too, and we had this conversation : > >> > >>> may be just = > >>> and time does not pass fast enough/ > >>> > >>>> On 03 Mar 2014, at 22:22, no-reply@ci.inria.fr wrote: > >>>> > >>>>> > https://ci.inria.fr/pharo/job/Pharo-3.0-Update-Step-2.1-Validation-A-L/label=linux-stable-worker/962/ > >>>>> > >>>>> 1 regressions found. > >>>>> KernelTests.Chronology.DateAndTimeTest.testMonotonicity > >>>> > >>>> How the hell can this fail ? > >>>> The clock moving backwards ?? > >>>> > >>>> testMonotonicity > >>>> > >>>> | t1 t2 t3 t4 | > >>>> t1 := DateAndTime now. > >>>> t2 := DateAndTime now. > >>>> (Delay forMilliseconds: 1000) wait. > >>>> t3 := DateAndTime now. > >>>> t4 := DateAndTime now. > >>>> > >>>> self > >>>> assert: (t1 <= t2); > >>>> assert: (t2 < t3); > >>>> assert: (t3 <= t4). > >> > >> > >> So you proofed Stef's assumption of time standing still ;-) > >> > >> But there were earlier problems as well. > >> > >> Thx ! > >> > >> On 04 Mar 2014, at 21:43, Max Leske <maxleske@gmail.com> wrote: > >> > >>> There seems to be a problem on > pharo-contribution-linux64-4.ci.inria.fr AFAICT. I can reproduce the > following to phenomena: > >>> > >>> 1. '(Delay forSeconds: 10) wait' does not wait. > >>> 2. 'DateAndTime now' does not change for long intervals. > >>> > >>> For instance, the following code: > >>> > >>> (FileSystem disk workingDirectory / 'foo.log') writeStreamDo: [ > :stream | > >>> stream nextPutAll: DateAndTime now asString;crlf. > >>> stream nextPutAll: ([(Delay forSeconds: 10) wait] timeToRun / > 1000) asString; crlf. > >>> stream nextPutAll: DateAndTime now asString ]. > >>> > >>> produces this output: > >>> > >>> 2014-03-04T21:32:21.396669+01:00 > >>> 0:00:00:00 > >>> 2014-03-04T21:32:21.396669+01:00 > >>> > >>> Too me (and my untrained eye) this looks like a system clock problem. > Could somebode take a look at the server in question? > >>> > >>> Cheers, > >>> Max > >> > >> > > > > > > > -- best, Eliot
participants (3)
-
Eliot Miranda -
Max Leske -
Sven Van Caekenberghe