I just recognized that Delay is working in a strange way on my linux box
$ time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait" a Delay(5000 msecs) real 0m0.158s user 0m0.136s sys 0m0.020s I use the vm from the ppa. What do you get when you execute it? Norbert |
It is even better, sometimes it works ;-)
# time ./pharo Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.696s user 0m0.580s sys 0m0.060s # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m5.755s user 0m0.812s sys 0m0.080s Weird ! Must have something todo with virtual hardware ... > On 28 Oct 2014, at 18:24, Norbert Hartl <[hidden email]> wrote: > > I just recognized that Delay is working in a strange way on my linux box > > $ time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait" > a Delay(5000 msecs) > > real 0m0.158s > user 0m0.136s > sys 0m0.020s > > I use the vm from the ppa. What do you get when you execute it? > > Norbert > |
VMWare Workstation 10 on Win8.1 Pro PharoVM compiled on CentOS6.5 [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.473s <-- not much... user 0m0.285s sys 0m0.140s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.360s <-- not much either user 0m0.257s sys 0m0.095s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.374s user 0m0.269s sys 0m0.103s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m5.324s user 0m0.338s sys 0m0.067s [philippeback@CENTOSDEV zeroconf-centos]$ [philippeback@CENTOSDEV zeroconf-centos]$ ^C <--- FROZEN!!!! [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.468s user 0m0.287s sys 0m0.171s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.639s user 0m0.281s sys 0m0.233s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.331s user 0m0.260s sys 0m0.066s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.493s user 0m0.265s sys 0m0.210s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.343s user 0m0.258s sys 0m0.073s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.352s user 0m0.314s sys 0m0.035s [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' a Delay(5000 msecs) real 0m0.303s user 0m0.266s sys 0m0.032s Completely un[reliable|predictable]... Phil # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' |
I am pretty sure that it is related to virtual hardware, it seems to work reliably on my mac:
prometheus:pharo4 sven$ ./pharo Pharo.image printVersion [version] 4.0 #40322 prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' a Delay(5000 msecs) real 0m5.504s user 0m0.491s sys 0m0.440s prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' a Delay(5000 msecs) real 0m5.539s user 0m0.408s sys 0m0.166s prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' a Delay(5000 msecs) real 0m6.022s user 0m0.647s sys 0m0.442s prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' a Delay(5000 msecs) real 0m5.539s user 0m0.518s sys 0m0.440s But how it can work so completely bogus on virtual hardware beats me. > On 28 Oct 2014, at 20:21, [hidden email] wrote: > > VMWare Workstation 10 on Win8.1 Pro > PharoVM compiled on CentOS6.5 > > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.473s <-- not much... > user 0m0.285s > sys 0m0.140s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.360s <-- not much either > user 0m0.257s > sys 0m0.095s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.374s > user 0m0.269s > sys 0m0.103s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > > a Delay(5000 msecs) > > real 0m5.324s > user 0m0.338s > sys 0m0.067s > [philippeback@CENTOSDEV zeroconf-centos]$ > [philippeback@CENTOSDEV zeroconf-centos]$ ^C <--- FROZEN!!!! > > > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.468s > user 0m0.287s > sys 0m0.171s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.639s > user 0m0.281s > sys 0m0.233s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.331s > user 0m0.260s > sys 0m0.066s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.493s > user 0m0.265s > sys 0m0.210s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.343s > user 0m0.258s > sys 0m0.073s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.352s > user 0m0.314s > sys 0m0.035s > [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.303s > user 0m0.266s > sys 0m0.032s > > > Completely un[reliable|predictable]... > > Phil > > # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m0.696s > user 0m0.580s > sys 0m0.060s > > # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' > a Delay(5000 msecs) > > real 0m5.755s > user 0m0.812s > sys 0m0.080s > > Weird ! > > Must have something todo with virtual hardware ... > > > On 28 Oct 2014, at 18:24, Norbert Hartl <[hidden email]> wrote: > > > > I just recognized that Delay is working in a strange way on my linux box > > > > $ time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait" > > a Delay(5000 msecs) > > > > real 0m0.158s > > user 0m0.136s > > sys 0m0.020s > > > > I use the vm from the ppa. What do you get when you execute it? > > > > Norbert > > > > > |
I have a report that it doesn't work on a linux desktop either. So at least there is one case where it does not work in a non-virtualized environment. Maybe interesting:
root@2d-misc:/opt/mock-server# time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait. (Delay forSeconds: 10) wait" a Delay(10000 msecs) real 0m10.185s user 0m0.268s sys 0m0.040s Norbert > Am 28.10.2014 um 22:56 schrieb Sven Van Caekenberghe <[hidden email]>: > > I am pretty sure that it is related to virtual hardware, it seems to work reliably on my mac: > > prometheus:pharo4 sven$ ./pharo Pharo.image printVersion > [version] 4.0 #40322 > > prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' > a Delay(5000 msecs) > > real 0m5.504s > user 0m0.491s > sys 0m0.440s > > prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' > a Delay(5000 msecs) > > real 0m5.539s > user 0m0.408s > sys 0m0.166s > > prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' > a Delay(5000 msecs) > > real 0m6.022s > user 0m0.647s > sys 0m0.442s > > prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' > a Delay(5000 msecs) > > real 0m5.539s > user 0m0.518s > sys 0m0.440s > > But how it can work so completely bogus on virtual hardware beats me. > >> On 28 Oct 2014, at 20:21, [hidden email] wrote: >> >> VMWare Workstation 10 on Win8.1 Pro >> PharoVM compiled on CentOS6.5 >> >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.473s <-- not much... >> user 0m0.285s >> sys 0m0.140s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.360s <-- not much either >> user 0m0.257s >> sys 0m0.095s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.374s >> user 0m0.269s >> sys 0m0.103s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> >> a Delay(5000 msecs) >> >> real 0m5.324s >> user 0m0.338s >> sys 0m0.067s >> [philippeback@CENTOSDEV zeroconf-centos]$ >> [philippeback@CENTOSDEV zeroconf-centos]$ ^C <--- FROZEN!!!! >> >> >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.468s >> user 0m0.287s >> sys 0m0.171s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.639s >> user 0m0.281s >> sys 0m0.233s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.331s >> user 0m0.260s >> sys 0m0.066s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.493s >> user 0m0.265s >> sys 0m0.210s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.343s >> user 0m0.258s >> sys 0m0.073s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.352s >> user 0m0.314s >> sys 0m0.035s >> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.303s >> user 0m0.266s >> sys 0m0.032s >> >> >> Completely un[reliable|predictable]... >> >> Phil >> >> # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m0.696s >> user 0m0.580s >> sys 0m0.060s >> >> # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m5.755s >> user 0m0.812s >> sys 0m0.080s >> >> Weird ! >> >> Must have something todo with virtual hardware ... >> >>> On 28 Oct 2014, at 18:24, Norbert Hartl <[hidden email]> wrote: >>> >>> I just recognized that Delay is working in a strange way on my linux box >>> >>> $ time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait" >>> a Delay(5000 msecs) >>> >>> real 0m0.158s >>> user 0m0.136s >>> sys 0m0.020s >>> >>> I use the vm from the ppa. What do you get when you execute it? >>> >>> Norbert >>> >> >> >> > > |
Norbert Hartl wrote:
> I have a report that it doesn't work on a linux desktop either. So at least there is one case where it does not work in a non-virtualized environment. Maybe interesting: > > root@2d-misc:/opt/mock-server# time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait. (Delay forSeconds: 10) wait" > a Delay(10000 msecs) > > real 0m10.185s > user 0m0.268s > sys 0m0.040s > > Norbert btw, coincidently I am working on refactoring Delay in two respects... Part 1. Delay class-side timer-priority-process methods are moved to instance side of new class DelayScheduler. Nominally this is to facilitate adding tests for Delay, and provide alternative forms of delay scheduling (e.g. mutex, semaphore, waitfree, spinlock). https://pharo.fogbugz.com/default.asp?14261 Part 2. change interthread synchronsiation for delay scheduling from Mutex to Semaphore https://pharo.fogbugz.com/default.asp?14344 Hopefully have Part2 done in a couple of days and it will be interesting to see whether this has any beneficial effect here. In the meantime, Part 1 may help you experiment without interfering with the normal operation of the system. In any case I'd be grateful for some feedback on Part 1. This effectively hasn't changed any functionality or the order of executing code. Its only moved code between a few methods. It would be great to pair up live with someone interested in it. cheers -ben > >> Am 28.10.2014 um 22:56 schrieb Sven Van Caekenberghe <[hidden email]>: >> >> I am pretty sure that it is related to virtual hardware, it seems to work reliably on my mac: >> >> prometheus:pharo4 sven$ ./pharo Pharo.image printVersion >> [version] 4.0 #40322 >> >> prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m5.504s >> user 0m0.491s >> sys 0m0.440s >> >> prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m5.539s >> user 0m0.408s >> sys 0m0.166s >> >> prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m6.022s >> user 0m0.647s >> sys 0m0.442s >> >> prometheus:pharo4 sven$ time ./pharo Pharo.image eval '5 seconds asDelay wait' >> a Delay(5000 msecs) >> >> real 0m5.539s >> user 0m0.518s >> sys 0m0.440s >> >> But how it can work so completely bogus on virtual hardware beats me. >> >>> On 28 Oct 2014, at 20:21, [hidden email] wrote: >>> >>> VMWare Workstation 10 on Win8.1 Pro >>> PharoVM compiled on CentOS6.5 >>> >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.473s <-- not much... >>> user 0m0.285s >>> sys 0m0.140s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.360s <-- not much either >>> user 0m0.257s >>> sys 0m0.095s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.374s >>> user 0m0.269s >>> sys 0m0.103s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> >>> a Delay(5000 msecs) >>> >>> real 0m5.324s >>> user 0m0.338s >>> sys 0m0.067s >>> [philippeback@CENTOSDEV zeroconf-centos]$ >>> [philippeback@CENTOSDEV zeroconf-centos]$ ^C <--- FROZEN!!!! >>> >>> >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.468s >>> user 0m0.287s >>> sys 0m0.171s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.639s >>> user 0m0.281s >>> sys 0m0.233s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.331s >>> user 0m0.260s >>> sys 0m0.066s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.493s >>> user 0m0.265s >>> sys 0m0.210s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.343s >>> user 0m0.258s >>> sys 0m0.073s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.352s >>> user 0m0.314s >>> sys 0m0.035s >>> [philippeback@CENTOSDEV zeroconf-centos]$ time ./pharo-vm/pharo -vm-display-null Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.303s >>> user 0m0.266s >>> sys 0m0.032s >>> >>> >>> Completely un[reliable|predictable]... >>> >>> Phil >>> >>> # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m0.696s >>> user 0m0.580s >>> sys 0m0.060s >>> >>> # time ./pharo Pharo.image eval '5 asSeconds asDelay wait' >>> a Delay(5000 msecs) >>> >>> real 0m5.755s >>> user 0m0.812s >>> sys 0m0.080s >>> >>> Weird ! >>> >>> Must have something todo with virtual hardware ... >>> >>>> On 28 Oct 2014, at 18:24, Norbert Hartl <[hidden email]> wrote: >>>> >>>> I just recognized that Delay is working in a strange way on my linux box >>>> >>>> $ time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait" >>>> a Delay(5000 msecs) >>>> >>>> real 0m0.158s >>>> user 0m0.136s >>>> sys 0m0.020s >>>> >>>> I use the vm from the ppa. What do you get when you execute it? >>>> >>>> Norbert >>>> >>> >>> >> > > > |
In reply to this post by NorbertHartl
On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote:
Good Evening, > I have a report that it doesn't work on a linux desktop either. So at least there is one case where it does not work in a non-virtualized environment. Maybe interesting: > > root@2d-misc:/opt/mock-server# time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait. (Delay forSeconds: 10) wait" > a Delay(10000 msecs) yes the first delay seems to fail. I have some holes in my analysis but so far I see: Process A (Delay forSeconds: 5) wait Delay class >> scheduleDelay aDelay resumptionTime: 5622 Process B Delay class >> handleTimerEvent is being executed "Check for clock wrap-around." nowTick := Time millisecondClockValue. nowTick < ActiveDelayStartTime ifTrue: [ "clock wrapped" ... self restoreResumptionTimes Delay class >> restoreResumptionTimes mydelay adjustResumptiomTimeOldBase: mydelay's resumptionTime is now negative. but the time base hasn't been changed as the Delay was started _after_ the image has been resumed (or at least while it is being resumed). ... nowTick >= ActiveDelay resumptionTime ifTrue: [ ActiveDelay signalWaitingProcess. What I notice is that: restoreResumptionTimes "Private! Restore the resumption times of all scheduled Delays after a snapshot or clock roll-over. This method should be called only while the AccessProtect semaphore is held." But handleTimerEvent doesn't seem to use AccessProtect. The comment and implementation appear to be not consistent. holger |
On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter Freyther wrote:
> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: > > Good Evening, Hi again, I don't know how you debug startUp issues. I just added an OrderedCollection into the systemdictionary and use it as a log.. time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | FileStream stderr nextPutAll: each printString; cr].1" ... old events from saving the image... {#handleTimerEvent->7147} {#handleTimerEvent->7167} {#resumptionTime->7187} {#handleTimerEvent->7167} {#handleTimerEvent->7187} {#start->true} {#start->393102159} {#start->393102159} {#resumptionTime->3279} {#handleTimerEvent->279} {#adjustResum->-393098880} {#restoreWithActiveDelay->266} {#adjustResum->-393098601} 1 real 0m0.294s user 0m0.244s sys 0m0.048s So what happens is Delay class>>#startU is called. and ActiveDelayStartTime is being set to 393102159. Then the delay is being created and resumptionTime is set to 3279. At the first time handleTimerEvent runs the milliSecondClock jumped backwards from 393102159 to 3279 which leads to an adjustment of the time. a.) Why does the time jump backwards like this during the resumption of the image? "3279" is not the old time nor the new starting time. b.) So even if that is a "wrap" around. Why does it go wrong? Are there unit tests for the clock wraps around? Maybe it is the same reason delays just don't work after image resumption? The "first" issue appears that when start is being executed that the clock is still wrong. At the same the clock is being considered wrapped the resumption time was actually already "correct' (3279 instead of 393102159+3279). Does this ring a bell? holger |
In reply to this post by Holger Freyther
Holger Hans Peter Freyther wrote:
> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: > > Good Evening, > >> I have a report that it doesn't work on a linux desktop either. So at least there is one case where it does not work in a non-virtualized environment. Maybe interesting: >> >> root@2d-misc:/opt/mock-server# time pharo-vm-nox ./Pharo.image eval "(Delay forSeconds: 5) wait. (Delay forSeconds: 10) wait" >> a Delay(10000 msecs) > > > yes the first delay seems to fail. I have some holes in my > analysis but so far I see: > > Process A > (Delay forSeconds: 5) wait > Delay class >> scheduleDelay > aDelay resumptionTime: 5622 > > Process B > Delay class >> handleTimerEvent is being executed > "Check for clock wrap-around." > nowTick := Time millisecondClockValue. > nowTick < ActiveDelayStartTime ifTrue: [ > "clock wrapped" > ... > self restoreResumptionTimes > > Delay class >> restoreResumptionTimes > mydelay adjustResumptiomTimeOldBase: > mydelay's resumptionTime is now negative. > but the time base hasn't been changed > as the Delay was started _after_ the > image has been resumed (or at least while > it is being resumed). > > ... nowTick >= ActiveDelay resumptionTime ifTrue: [ > ActiveDelay signalWaitingProcess. > > > > What I notice is that: > > restoreResumptionTimes > "Private! Restore the resumption times of all scheduled Delays after a snapshot or clock roll-over. This method should be called only while the AccessProtect semaphore is held." > > But handleTimerEvent doesn't seem to use AccessProtect. The comment > and implementation appear to be not consistent. > > holger > > > #handleTimerEvent runs in the highest priority process at TimingPriority=80. The AccessProtect mutex is about controlling how multiple lower priority processes poke instances of Delay into the ScheduledDelay and FinishedDelay variables for #handleTimerEvent to process (being invoked by signaling TimingSempahore from within the AccessProtect). However restoreResumptionTimes is also called from #startUp by low priority processes and that is probably when AccessProtect is required. However2, I am working on an alternative implementation to use Semaphores rather than the AccessProtect mutex, which should bypass your concern. It should be ready for review early next week. cheers -ben |
In reply to this post by Holger Freyther
Holger Hans Peter Freyther wrote:
> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter Freyther wrote: >> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >> >> Good Evening, > > Hi again, > > I don't know how you debug startUp issues. I just added an OrderedCollection > into the systemdictionary and use it as a log.. > > time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | FileStream stderr nextPutAll: each printString; cr].1" > ... old events from saving the image... > {#handleTimerEvent->7147} > {#handleTimerEvent->7167} > {#resumptionTime->7187} > {#handleTimerEvent->7167} > {#handleTimerEvent->7187} > {#start->true} > {#start->393102159} > {#start->393102159} > {#resumptionTime->3279} > {#handleTimerEvent->279} > {#adjustResum->-393098880} > {#restoreWithActiveDelay->266} > {#adjustResum->-393098601} > 1 > > real 0m0.294s > user 0m0.244s > sys 0m0.048s > > > So what happens is Delay class>>#startU is called. and > ActiveDelayStartTime is being set to 393102159. Then the > delay is being created and resumptionTime is set to 3279. > At the first time handleTimerEvent runs the milliSecondClock > jumped backwards from 393102159 to 3279 which leads to > an adjustment of the time. > > > a.) Why does the time jump backwards like this during the > resumption of the image? "3279" is not the old time nor > the new starting time. > > b.) So even if that is a "wrap" around. Why does it go > wrong? Are there unit tests for the clock wraps around? There are no unit tests, I guess since its all done using class variables its too hard test without disturbing the system. Now I have spent the last week refactoring this out to the instance-side of a new class "DelayScheduler" which should help with getting unit tests. Its ready for review [1], maybe you could take a look. [1] https://pharo.fogbugz.com/default.asp?14261 > Maybe it is the same reason delays just don't work after > image resumption? > > The "first" issue appears that when start is being executed > that the clock is still wrong. At the same the clock is > being considered wrapped the resumption time was actually > already "correct' (3279 instead of 393102159+3279). > > Does this ring a bell? > > holger > > btw, its too late in the night for me to try something, but I have been wondering, should the check for clock roll-over occur immediately after TimingSemaphore wait wakes up. That is, before the Schedule and Finish requests are handled ??? cheers -ben |
On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email]> wrote: --
The check for rollover should be thrown away and the system implemented over the VM's support for 64-bit microseconds since 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't require the millisecond clock to be synced to the second clock, because all times can be derived from the one 64-bit microsecond clock. best, Eliot
|
Eliot Miranda wrote:
> > > On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] > <mailto:[hidden email]>> wrote: > > Holger Hans Peter Freyther wrote: > > On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter > Freyther wrote: > > On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: > > Good Evening, > > > Hi again, > > I don't know how you debug startUp issues. I just added an > OrderedCollection > into the systemdictionary and use it as a log.. > > time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay > forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | > FileStream stderr nextPutAll: each printString; cr].1" > ... old events from saving the image... > {#handleTimerEvent->7147} > {#handleTimerEvent->7167} > {#resumptionTime->7187} > {#handleTimerEvent->7167} > {#handleTimerEvent->7187} > {#start->true} > {#start->393102159} > {#start->393102159} > {#resumptionTime->3279} > {#handleTimerEvent->279} > {#adjustResum->-393098880} > {#restoreWithActiveDelay->266} > {#adjustResum->-393098601} > 1 > > real 0m0.294s > user 0m0.244s > sys 0m0.048s > > > So what happens is Delay class>>#startU is called. and > ActiveDelayStartTime is being set to 393102159. Then the > delay is being created and resumptionTime is set to 3279. > At the first time handleTimerEvent runs the milliSecondClock > jumped backwards from 393102159 to 3279 which leads to > an adjustment of the time. > > > a.) Why does the time jump backwards like this during the > resumption of the image? "3279" is not the old time nor > the new starting time. > > b.) So even if that is a "wrap" around. Why does it go > wrong? Are there unit tests for the clock wraps around? > > > There are no unit tests, I guess since its all done using class > variables its too hard test without disturbing the system. > > Now I have spent the last week refactoring this out to the > instance-side of a new class "DelayScheduler" which should help with > getting unit tests. Its ready for review [1], maybe you could take > a look. > > [1] https://pharo.fogbugz.com/__default.asp?14261 > <https://pharo.fogbugz.com/default.asp?14261> > > Maybe it is the same reason delays just don't work after > image resumption? > > The "first" issue appears that when start is being executed > that the clock is still wrong. At the same the clock is > being considered wrapped the resumption time was actually > already "correct' (3279 instead of 393102159+3279). > > Does this ring a bell? > > holger > > > > btw, its too late in the night for me to try something, but I have > been wondering, should the check for clock roll-over occur > immediately after > TimingSemaphore wait > wakes up. That is, before the Schedule and Finish requests are > handled ??? > > > The check for rollover should be thrown away and the system implemented > over the VM's support for 64-bit microseconds since 1901. It's in the > VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't > require the millisecond clock to be synced to the second clock, because > all times can be derived from the one 64-bit microsecond clock. > > -- > best, > Eliot I'll give it a go. cheers -ben |
> Am 30.10.2014 um 12:52 schrieb Ben Coman <[hidden email]>: > > Eliot Miranda wrote: >> On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] <mailto:[hidden email]>> wrote: >> Holger Hans Peter Freyther wrote: >> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter >> Freyther wrote: >> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >> Good Evening, >> Hi again, >> I don't know how you debug startUp issues. I just added an >> OrderedCollection >> into the systemdictionary and use it as a log.. >> time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay >> forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | >> FileStream stderr nextPutAll: each printString; cr].1" >> ... old events from saving the image... >> {#handleTimerEvent->7147} >> {#handleTimerEvent->7167} >> {#resumptionTime->7187} >> {#handleTimerEvent->7167} >> {#handleTimerEvent->7187} >> {#start->true} >> {#start->393102159} >> {#start->393102159} >> {#resumptionTime->3279} >> {#handleTimerEvent->279} >> {#adjustResum->-393098880} >> {#restoreWithActiveDelay->266} >> {#adjustResum->-393098601} >> 1 >> real 0m0.294s >> user 0m0.244s >> sys 0m0.048s >> So what happens is Delay class>>#startU is called. and >> ActiveDelayStartTime is being set to 393102159. Then the >> delay is being created and resumptionTime is set to 3279. >> At the first time handleTimerEvent runs the milliSecondClock >> jumped backwards from 393102159 to 3279 which leads to >> an adjustment of the time. >> a.) Why does the time jump backwards like this during the >> resumption of the image? "3279" is not the old time nor >> the new starting time. >> b.) So even if that is a "wrap" around. Why does it go >> wrong? Are there unit tests for the clock wraps around? >> There are no unit tests, I guess since its all done using class >> variables its too hard test without disturbing the system. >> Now I have spent the last week refactoring this out to the >> instance-side of a new class "DelayScheduler" which should help with >> getting unit tests. Its ready for review [1], maybe you could take >> a look. >> [1] https://pharo.fogbugz.com/__default.asp?14261 >> <https://pharo.fogbugz.com/default.asp?14261> >> Maybe it is the same reason delays just don't work after >> image resumption? >> The "first" issue appears that when start is being executed >> that the clock is still wrong. At the same the clock is >> being considered wrapped the resumption time was actually >> already "correct' (3279 instead of 393102159+3279). >> Does this ring a bell? >> holger >> btw, its too late in the night for me to try something, but I have >> been wondering, should the check for clock roll-over occur >> immediately after >> TimingSemaphore wait >> wakes up. That is, before the Schedule and Finish requests are >> handled ??? >> The check for rollover should be thrown away and the system implemented over the VM's support for 64-bit microseconds since 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't require the millisecond clock to be synced to the second clock, because all times can be derived from the one 64-bit microsecond clock. >> -- >> best, >> Eliot > > I'll give it a go. > cheers -ben > Norbert |
In reply to this post by Ben Coman
We really need people to have a look at the code of Ben.
Stef On 29/10/14 15:02, Ben Coman wrote: > Holger Hans Peter Freyther wrote: >> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >> >> Good Evening, >> >>> I have a report that it doesn't work on a linux desktop either. So >>> at least there is one case where it does not work in a >>> non-virtualized environment. Maybe interesting: >>> root@2d-misc:/opt/mock-server# time pharo-vm-nox ./Pharo.image eval >>> "(Delay forSeconds: 5) wait. (Delay forSeconds: 10) wait" >>> a Delay(10000 msecs) >> >> >> yes the first delay seems to fail. I have some holes in my >> analysis but so far I see: >> >> Process A >> (Delay forSeconds: 5) wait >> Delay class >> scheduleDelay >> aDelay resumptionTime: 5622 >> >> Process B >> Delay class >> handleTimerEvent is being executed >> "Check for clock wrap-around." >> nowTick := Time millisecondClockValue. >> nowTick < ActiveDelayStartTime ifTrue: [ >> "clock wrapped" >> ... >> self restoreResumptionTimes >> >> Delay class >> restoreResumptionTimes >> mydelay adjustResumptiomTimeOldBase: >> mydelay's resumptionTime is now negative. >> but the time base hasn't been changed >> as the Delay was started _after_ the >> image has been resumed (or at least while >> it is being resumed). >> >> ... nowTick >= ActiveDelay resumptionTime ifTrue: [ >> ActiveDelay signalWaitingProcess. >> >> >> >> What I notice is that: >> >> restoreResumptionTimes >> "Private! Restore the resumption times of all scheduled Delays >> after a snapshot or clock roll-over. This method should be called >> only while the AccessProtect semaphore is held." >> >> But handleTimerEvent doesn't seem to use AccessProtect. The comment >> and implementation appear to be not consistent. >> >> holger >> >> >> > > #handleTimerEvent runs in the highest priority process at > TimingPriority=80. The AccessProtect mutex is about controlling how > multiple lower priority processes poke instances of Delay into the > ScheduledDelay and FinishedDelay variables for #handleTimerEvent to > process (being invoked by signaling TimingSempahore from within the > AccessProtect). > > However restoreResumptionTimes is also called from #startUp by low > priority processes and that is probably when AccessProtect is required. > > However2, I am working on an alternative implementation to use > Semaphores rather than the AccessProtect mutex, which should bypass > your concern. It should be ready for review early next week. > > cheers -ben > > > |
In reply to this post by NorbertHartl
Norbert Hartl wrote:
>> Am 30.10.2014 um 12:52 schrieb Ben Coman <[hidden email]>: >> >> Eliot Miranda wrote: >>> On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] <mailto:[hidden email]>> wrote: >>> Holger Hans Peter Freyther wrote: >>> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter >>> Freyther wrote: >>> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >>> Good Evening, >>> Hi again, >>> I don't know how you debug startUp issues. I just added an >>> OrderedCollection >>> into the systemdictionary and use it as a log.. >>> time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay >>> forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | >>> FileStream stderr nextPutAll: each printString; cr].1" >>> ... old events from saving the image... >>> {#handleTimerEvent->7147} >>> {#handleTimerEvent->7167} >>> {#resumptionTime->7187} >>> {#handleTimerEvent->7167} >>> {#handleTimerEvent->7187} >>> {#start->true} >>> {#start->393102159} >>> {#start->393102159} >>> {#resumptionTime->3279} >>> {#handleTimerEvent->279} >>> {#adjustResum->-393098880} >>> {#restoreWithActiveDelay->266} >>> {#adjustResum->-393098601} >>> 1 >>> real 0m0.294s >>> user 0m0.244s >>> sys 0m0.048s >>> So what happens is Delay class>>#startU is called. and >>> ActiveDelayStartTime is being set to 393102159. Then the >>> delay is being created and resumptionTime is set to 3279. >>> At the first time handleTimerEvent runs the milliSecondClock >>> jumped backwards from 393102159 to 3279 which leads to >>> an adjustment of the time. >>> a.) Why does the time jump backwards like this during the >>> resumption of the image? "3279" is not the old time nor >>> the new starting time. >>> b.) So even if that is a "wrap" around. Why does it go >>> wrong? Are there unit tests for the clock wraps around? >>> There are no unit tests, I guess since its all done using class >>> variables its too hard test without disturbing the system. >>> Now I have spent the last week refactoring this out to the >>> instance-side of a new class "DelayScheduler" which should help with >>> getting unit tests. Its ready for review [1], maybe you could take >>> a look. >>> [1] https://pharo.fogbugz.com/__default.asp?14261 >>> <https://pharo.fogbugz.com/default.asp?14261> >>> Maybe it is the same reason delays just don't work after >>> image resumption? >>> The "first" issue appears that when start is being executed >>> that the clock is still wrong. At the same the clock is >>> being considered wrapped the resumption time was actually >>> already "correct' (3279 instead of 393102159+3279). >>> Does this ring a bell? >>> holger >>> btw, its too late in the night for me to try something, but I have >>> been wondering, should the check for clock roll-over occur >>> immediately after >>> TimingSemaphore wait >>> wakes up. That is, before the Schedule and Finish requests are >>> handled ??? >>> The check for rollover should be thrown away and the system implemented over the VM's support for 64-bit microseconds since 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't require the millisecond clock to be synced to the second clock, because all times can be derived from the one 64-bit microsecond clock. >>> -- >>> best, >>> Eliot >> I'll give it a go. >> cheers -ben >> > Super, thanks in advance, > > Norbert > > > > This is ready for review as "Delay refactoring (part 2) - change from milliseconds to microseconds" https://pharo.fogbugz.com/default.asp?14353 Note that this continues on from "Delay refactoring (part 1) - move scheduler from class-side to instance-side of its own class" https://pharo.fogbugz.com/default.asp?14261 So load part 1 first if you only want to see the from milliseconds to microseconds changes. Now if you don't like part 1, I'll do the work to break out part 2 on its own - but it was simpler for me to work on part 2 since: * with instances I could define, run and debug tests without interference from the live system-delay-scheduler. * the code swapping (newCodeEnabled) pattern I'd used for part 1 helped. * eliminating the clock rollover conditional simplifies what I am planning for part 3 I don't have the virtual machine environment to replicate the problem, so please report if it this has any effect. cheers -ben |
Ben Coman wrote:
> Norbert Hartl wrote: >>> Am 30.10.2014 um 12:52 schrieb Ben Coman <[hidden email]>: >>> >>> Eliot Miranda wrote: >>>> On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] >>>> <mailto:[hidden email]>> wrote: >>>> Holger Hans Peter Freyther wrote: >>>> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter >>>> Freyther wrote: >>>> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl >>>> wrote: >>>> Good Evening, >>>> Hi again, >>>> I don't know how you debug startUp issues. I just added an >>>> OrderedCollection >>>> into the systemdictionary and use it as a log.. >>>> time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay >>>> forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | >>>> FileStream stderr nextPutAll: each printString; cr].1" >>>> ... old events from saving the image... >>>> {#handleTimerEvent->7147} >>>> {#handleTimerEvent->7167} >>>> {#resumptionTime->7187} >>>> {#handleTimerEvent->7167} >>>> {#handleTimerEvent->7187} >>>> {#start->true} >>>> {#start->393102159} >>>> {#start->393102159} >>>> {#resumptionTime->3279} >>>> {#handleTimerEvent->279} >>>> {#adjustResum->-393098880} >>>> {#restoreWithActiveDelay->266} >>>> {#adjustResum->-393098601} >>>> 1 >>>> real 0m0.294s >>>> user 0m0.244s >>>> sys 0m0.048s >>>> So what happens is Delay class>>#startU is called. and >>>> ActiveDelayStartTime is being set to 393102159. Then the >>>> delay is being created and resumptionTime is set to 3279. >>>> At the first time handleTimerEvent runs the milliSecondClock >>>> jumped backwards from 393102159 to 3279 which leads to >>>> an adjustment of the time. >>>> a.) Why does the time jump backwards like this during the >>>> resumption of the image? "3279" is not the old time nor >>>> the new starting time. >>>> b.) So even if that is a "wrap" around. Why does it go >>>> wrong? Are there unit tests for the clock wraps around? >>>> There are no unit tests, I guess since its all done using class >>>> variables its too hard test without disturbing the system. >>>> Now I have spent the last week refactoring this out to the >>>> instance-side of a new class "DelayScheduler" which should help with >>>> getting unit tests. Its ready for review [1], maybe you could take >>>> a look. >>>> [1] https://pharo.fogbugz.com/__default.asp?14261 >>>> <https://pharo.fogbugz.com/default.asp?14261> >>>> Maybe it is the same reason delays just don't work after >>>> image resumption? >>>> The "first" issue appears that when start is being executed >>>> that the clock is still wrong. At the same the clock is >>>> being considered wrapped the resumption time was actually >>>> already "correct' (3279 instead of 393102159+3279). >>>> Does this ring a bell? >>>> holger >>>> btw, its too late in the night for me to try something, but I have >>>> been wondering, should the check for clock roll-over occur >>>> immediately after >>>> TimingSemaphore wait >>>> wakes up. That is, before the Schedule and Finish requests are >>>> handled ??? >>>> The check for rollover should be thrown away and the system >>>> implemented over the VM's support for 64-bit microseconds since >>>> 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 >>>> years, and doesn't require the millisecond clock to be synced to the >>>> second clock, because all times can be derived from the one 64-bit >>>> microsecond clock. >>>> -- >>>> best, >>>> Eliot >>> I'll give it a go. >>> cheers -ben >>> >> Super, thanks in advance, >> >> Norbert >> >> >> >> > > This is ready for review as "Delay refactoring (part 2) - change from > milliseconds to microseconds" > https://pharo.fogbugz.com/default.asp?14353 > > Note that this continues on from "Delay refactoring (part 1) - move > scheduler from class-side to instance-side of its own class" > https://pharo.fogbugz.com/default.asp?14261 > > So load part 1 first if you only want to see the from milliseconds to > microseconds changes. Now if you don't like part 1, I'll do the work to > break out part 2 on its own - but it was simpler for me to work on part > 2 since: > * with instances I could define, run and debug tests without > interference from the live system-delay-scheduler. > * the code swapping (newCodeEnabled) pattern I'd used for part 1 helped. > * eliminating the clock rollover conditional simplifies what I am > planning for part 3 > > I don't have the virtual machine environment to replicate the problem, > so please report if it this has any effect. > > cheers -ben > > I've confirmed this works with build 40346 on LinuxMint17 on Virtualbox on OSX. With the following script test.sh... ---- #!/bin/bash for i in `seq 1 20` ; do (time pharo-vm-nox ./test.image \ eval "(Delay forSeconds: 2) wait") 2>&1 > /dev/null | grep real done ---- I get... # bash ./test.sh real 0m0.160s real 0m2.159s real 0m0.161s real 0m0.176s real 0m2.158s real 0m0.160s real 0m0.157s real 0m0.170s real 0m0.154s real 0m0.156s real 0m0.159s real 0m2.161s real 0m0.156s real 0m0.149s real 0m0.158s real 0m0.167s real 0m0.162s real 0m2.152s real 0m0.212s real 0m2.212s In the image load slice 14353, then evaluate "Delay newCodeEnabled: true", and save the image. Then from the shell... # ./test.sh real 0m2.161s real 0m2.156s real 0m2.206s real 0m2.170s real 0m2.156s real 0m2.162s real 0m2.158s real 0m2.163s real 0m2.158s real 0m2.158s real 0m2.163s real 0m2.168s real 0m2.162s real 0m2.158s real 0m2.162s real 0m2.164s real 0m2.153s real 0m2.152s real 0m2.198s real 0m2.173s cheers -ben |
In reply to this post by Eliot Miranda-2
Eliot Miranda wrote:
> > > On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] > <mailto:[hidden email]>> wrote: > > Holger Hans Peter Freyther wrote: > > On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter > Freyther wrote: > > On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: > > Good Evening, > > > Hi again, > > I don't know how you debug startUp issues. I just added an > OrderedCollection > into the systemdictionary and use it as a log.. > > time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay > forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | > FileStream stderr nextPutAll: each printString; cr].1" > ... old events from saving the image... > {#handleTimerEvent->7147} > {#handleTimerEvent->7167} > {#resumptionTime->7187} > {#handleTimerEvent->7167} > {#handleTimerEvent->7187} > {#start->true} > {#start->393102159} > {#start->393102159} > {#resumptionTime->3279} > {#handleTimerEvent->279} > {#adjustResum->-393098880} > {#restoreWithActiveDelay->266} > {#adjustResum->-393098601} > 1 > > real 0m0.294s > user 0m0.244s > sys 0m0.048s > > > So what happens is Delay class>>#startU is called. and > ActiveDelayStartTime is being set to 393102159. Then the > delay is being created and resumptionTime is set to 3279. > At the first time handleTimerEvent runs the milliSecondClock > jumped backwards from 393102159 to 3279 which leads to > an adjustment of the time. > > > a.) Why does the time jump backwards like this during the > resumption of the image? "3279" is not the old time nor > the new starting time. > > b.) So even if that is a "wrap" around. Why does it go > wrong? Are there unit tests for the clock wraps around? > > > There are no unit tests, I guess since its all done using class > variables its too hard test without disturbing the system. > > Now I have spent the last week refactoring this out to the > instance-side of a new class "DelayScheduler" which should help with > getting unit tests. Its ready for review [1], maybe you could take > a look. > > [1] https://pharo.fogbugz.com/__default.asp?14261 > <https://pharo.fogbugz.com/default.asp?14261> > > Maybe it is the same reason delays just don't work after > image resumption? > > The "first" issue appears that when start is being executed > that the clock is still wrong. At the same the clock is > being considered wrapped the resumption time was actually > already "correct' (3279 instead of 393102159+3279). > > Does this ring a bell? > > holger > > > > btw, its too late in the night for me to try something, but I have > been wondering, should the check for clock roll-over occur > immediately after > TimingSemaphore wait > wakes up. That is, before the Schedule and Finish requests are > handled ??? > > > The check for rollover should be thrown away and the system implemented > over the VM's support for 64-bit microseconds since 1901. It's in the > VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't > require the millisecond clock to be synced to the second clock, because > all times can be derived from the one 64-bit microsecond clock. > > -- > best, > Eliot The performance of the Delay timer event loop is noted in the code to be critical, however... "Time millisecondClockValue" returns a SmallInteger, which is an immediate object while "Time microsecondClockValue" returns a LargePositiveInteger, which is not. So theoretically will calculations and comparisons based on the second be slower ? Actually my performance testing so far hasn't found it to be slower, but I am interested in the general case. cheers -ben |
Hi Ben,
On Nov 2, 2014, at 6:06 AM, Ben Coman <[hidden email]> wrote: > Eliot Miranda wrote: >> On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] <mailto:[hidden email]>> wrote: >> Holger Hans Peter Freyther wrote: >> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter >> Freyther wrote: >> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >> Good Evening, >> Hi again, >> I don't know how you debug startUp issues. I just added an >> OrderedCollection >> into the systemdictionary and use it as a log.. >> time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay >> forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | >> FileStream stderr nextPutAll: each printString; cr].1" >> ... old events from saving the image... >> {#handleTimerEvent->7147} >> {#handleTimerEvent->7167} >> {#resumptionTime->7187} >> {#handleTimerEvent->7167} >> {#handleTimerEvent->7187} >> {#start->true} >> {#start->393102159} >> {#start->393102159} >> {#resumptionTime->3279} >> {#handleTimerEvent->279} >> {#adjustResum->-393098880} >> {#restoreWithActiveDelay->266} >> {#adjustResum->-393098601} >> 1 >> real 0m0.294s >> user 0m0.244s >> sys 0m0.048s >> So what happens is Delay class>>#startU is called. and >> ActiveDelayStartTime is being set to 393102159. Then the >> delay is being created and resumptionTime is set to 3279. >> At the first time handleTimerEvent runs the milliSecondClock >> jumped backwards from 393102159 to 3279 which leads to >> an adjustment of the time. >> a.) Why does the time jump backwards like this during the >> resumption of the image? "3279" is not the old time nor >> the new starting time. >> b.) So even if that is a "wrap" around. Why does it go >> wrong? Are there unit tests for the clock wraps around? >> There are no unit tests, I guess since its all done using class >> variables its too hard test without disturbing the system. >> Now I have spent the last week refactoring this out to the >> instance-side of a new class "DelayScheduler" which should help with >> getting unit tests. Its ready for review [1], maybe you could take >> a look. >> [1] https://pharo.fogbugz.com/__default.asp?14261 >> <https://pharo.fogbugz.com/default.asp?14261> >> Maybe it is the same reason delays just don't work after >> image resumption? >> The "first" issue appears that when start is being executed >> that the clock is still wrong. At the same the clock is >> being considered wrapped the resumption time was actually >> already "correct' (3279 instead of 393102159+3279). >> Does this ring a bell? >> holger >> btw, its too late in the night for me to try something, but I have >> been wondering, should the check for clock roll-over occur >> immediately after >> TimingSemaphore wait >> wakes up. That is, before the Schedule and Finish requests are >> handled ??? >> The check for rollover should be thrown away and the system implemented over the VM's support for 64-bit microseconds since 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't require the millisecond clock to be synced to the second clock, because all times can be derived from the one 64-bit microsecond clock. >> -- >> best, >> Eliot > > The performance of the Delay timer event loop is noted in the code to be critical, however... > > "Time millisecondClockValue" returns a SmallInteger, which is an immediate object while "Time microsecondClockValue" returns a LargePositiveInteger, which is not. > > So theoretically will calculations and comparisons based on the second be slower ? Actually my performance testing so far hasn't found it to be slower, but I am interested in the general case. That comment was written when the context interpreter VM was the standard. Cog is much faster. That should more than make up for the small amount of large integer arithmetic the use of 64-bit microseconds involves. And once we switch to 64-bit Spur the 64-bit microsecond clock will once again be a SmalInteger. And if your measurements show you there isn't an issue then there isn't an issue. > > cheers -ben |
Eliot Miranda wrote:
> > Hi Ben, > > On Nov 2, 2014, at 6:06 AM, Ben Coman <[hidden email]> wrote: > >> Eliot Miranda wrote: >>> On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[hidden email] <mailto:[hidden email]>> wrote: >>> Holger Hans Peter Freyther wrote: >>> On Wed, Oct 29, 2014 at 06:54:57PM +0100, Holger Hans Peter >>> Freyther wrote: >>> On Wed, Oct 29, 2014 at 10:03:03AM +0100, Norbert Hartl wrote: >>> Good Evening, >>> Hi again, >>> I don't know how you debug startUp issues. I just added an >>> OrderedCollection >>> into the systemdictionary and use it as a log.. >>> time ./bin/pharo --nodisplay ./TimerTest3.image eval "(Delay >>> forSeconds: 3) wait. (Smalltalk at: #Foo) do: [:each | >>> FileStream stderr nextPutAll: each printString; cr].1" >>> ... old events from saving the image... >>> {#handleTimerEvent->7147} >>> {#handleTimerEvent->7167} >>> {#resumptionTime->7187} >>> {#handleTimerEvent->7167} >>> {#handleTimerEvent->7187} >>> {#start->true} >>> {#start->393102159} >>> {#start->393102159} >>> {#resumptionTime->3279} >>> {#handleTimerEvent->279} >>> {#adjustResum->-393098880} >>> {#restoreWithActiveDelay->266} >>> {#adjustResum->-393098601} >>> 1 >>> real 0m0.294s >>> user 0m0.244s >>> sys 0m0.048s >>> So what happens is Delay class>>#startU is called. and >>> ActiveDelayStartTime is being set to 393102159. Then the >>> delay is being created and resumptionTime is set to 3279. >>> At the first time handleTimerEvent runs the milliSecondClock >>> jumped backwards from 393102159 to 3279 which leads to >>> an adjustment of the time. >>> a.) Why does the time jump backwards like this during the >>> resumption of the image? "3279" is not the old time nor >>> the new starting time. >>> b.) So even if that is a "wrap" around. Why does it go >>> wrong? Are there unit tests for the clock wraps around? >>> There are no unit tests, I guess since its all done using class >>> variables its too hard test without disturbing the system. >>> Now I have spent the last week refactoring this out to the >>> instance-side of a new class "DelayScheduler" which should help with >>> getting unit tests. Its ready for review [1], maybe you could take >>> a look. >>> [1] https://pharo.fogbugz.com/__default.asp?14261 >>> <https://pharo.fogbugz.com/default.asp?14261> >>> Maybe it is the same reason delays just don't work after >>> image resumption? >>> The "first" issue appears that when start is being executed >>> that the clock is still wrong. At the same the clock is >>> being considered wrapped the resumption time was actually >>> already "correct' (3279 instead of 393102159+3279). >>> Does this ring a bell? >>> holger >>> btw, its too late in the night for me to try something, but I have >>> been wondering, should the check for clock roll-over occur >>> immediately after >>> TimingSemaphore wait >>> wakes up. That is, before the Schedule and Finish requests are >>> handled ??? >>> The check for rollover should be thrown away and the system implemented over the VM's support for 64-bit microseconds since 1901. It's in the VM, it isn't susceptible to rollover for ~ 50,000 years, and doesn't require the millisecond clock to be synced to the second clock, because all times can be derived from the one 64-bit microsecond clock. >>> -- >>> best, >>> Eliot >> The performance of the Delay timer event loop is noted in the code to be critical, however... >> >> "Time millisecondClockValue" returns a SmallInteger, which is an immediate object while "Time microsecondClockValue" returns a LargePositiveInteger, which is not. >> >> So theoretically will calculations and comparisons based on the second be slower ? Actually my performance testing so far hasn't found it to be slower, but I am interested in the general case. > > That comment was written when the context interpreter VM was the standard. Cog is much faster. That should more than make up for the small amount of large integer arithmetic the use of 64-bit microseconds involves. And once we switch to 64-bit Spur the 64-bit microsecond clock will once again be a SmalInteger. And if your measurements show you there isn't an issue then there isn't an issue. > Cool. Thanks for the info. |
In reply to this post by stepharo
On Thu, Oct 30, 2014 at 06:32:48PM -0400, stepharo wrote:
Good Morning Ben, Stef, > We really need people to have a look at the code of Ben. I downloaded a Pharo-4 image today and executed: time pharo --nodisplay --headless ./Pharo-40490.image eval "(Delay forSeconds: 5) wait" a Delay(5000 msecs) real 0m1.254s user 0m1.192s sys 0m0.060s So the first delay doesn't appear to wait the five seconds. I would like to work on kqueue/epoll and remove polling and it looks this involves code with Delay as well. I wonder if you could provide an overview of what needs to be done and what is done? thanks holger |
Free forum by Nabble | Edit this page |