Super fast delay

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
32 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Super fast delay

NorbertHartl
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

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Sven Van Caekenberghe-2
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
>


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

philippeback
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
>



Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Sven Van Caekenberghe-2
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
> >
>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

NorbertHartl
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
>>>
>>
>>
>>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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
>>>>
>>>
>>>
>>
>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Holger Freyther
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


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Holger Freyther
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

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Eliot Miranda-2


On Wed, Oct 29, 2014 at 12:14 PM, Ben Coman <[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

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
Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

NorbertHartl

> 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



Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

stepharo
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
>
>
>


Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Ben Coman
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

Reply | Threaded
Open this post in threaded view
|

Re: [Vm-dev] Re: Super fast delay

Eliot Miranda-2
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

Reply | Threaded
Open this post in threaded view
|

Re: [Vm-dev] Re: Super fast delay

Ben Coman
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.

Reply | Threaded
Open this post in threaded view
|

Re: Super fast delay

Holger Freyther
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



12