Comparison of actual and expected Delay length on small durations

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

Comparison of actual and expected Delay length on small durations

Aliaksei Syrel
Hi

At some point I got a feeling that actual Delay time is longer than expected. It is especially visible on small delays less than 100ms (otherwise difference is < 1%).

Inline image 1
Documentation says that Delay waits approximately for specified amount of time. However, according to experimental data an actual difference is always positive with the value around 1.5-2 seconds. It is actually strange where such a constant difference, independent from delay length, comes from.
Inline image 2
To conclude, if you want to wait more precisely you need to create delays with duration 1.5 seconds less than expected. Also it would be interesting to test on different hardwares to make sure that difference stays constant (around 1.5-2s)

I used the following script to gather data and save in .csv file

Tested on:
Pharo: #50636
Spur-VM: #463
OS: Mac OS Yosemite
CPU: Intel Core i7 2.39 GHz

Cheers,
Alex

Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Aliaksei Syrel
Difference is in milliseconds, sorry :)

On Sat, Mar 12, 2016 at 6:47 PM, Aliaksei Syrel <[hidden email]> wrote:
Hi

At some point I got a feeling that actual Delay time is longer than expected. It is especially visible on small delays less than 100ms (otherwise difference is < 1%).

Inline image 1
Documentation says that Delay waits approximately for specified amount of time. However, according to experimental data an actual difference is always positive with the value around 1.5-2 seconds. It is actually strange where such a constant difference, independent from delay length, comes from.
Inline image 2
To conclude, if you want to wait more precisely you need to create delays with duration 1.5 seconds less than expected. Also it would be interesting to test on different hardwares to make sure that difference stays constant (around 1.5-2s)

I used the following script to gather data and save in .csv file

Tested on:
Pharo: #50636
Spur-VM: #463
OS: Mac OS Yosemite
CPU: Intel Core i7 2.39 GHz

Cheers,
Alex


Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

CyrilFerlicot
In reply to this post by Aliaksei Syrel
Le 12/03/2016 18:47, Aliaksei Syrel a écrit :

> Hi
>
> At some point I got a feeling that actual Delay time is longer than
> expected. It is especially visible on small delays less than 100ms
> (otherwise difference is < 1%).
>
> Inline image 1
> Documentation says that _Delay waits approximately_ for specified amount
> of time. However, according to experimental data an actual difference is
> always positive with the value around 1.5-2 seconds. It is actually
> strange where such a constant difference, independent from delay length,
> comes from.
> Inline image 2
> To conclude, if you want to wait more precisely you need to create
> delays with duration 1.5 seconds less than expected. Also it would be
> interesting to test on different hardwares to make sure that difference
> stays constant (around 1.5-2s)
>
> I used the following script to gather data and save in .csv file
> http://ws.stfx.eu/DSCLG2ON0VBI
>
> Tested on:
> Pharo: #50636
> Spur-VM: #463
> OS: Mac OS Yosemite
> CPU: Intel Core i7 2.39 GHz
>
> Cheers,
> Alex
>
If you wish to compare I join a csv. This is my setup:

Image
-----
C:\Users\JeCisC\AppData\Roaming\Pharo\images\Common tools-Pharo 5.0
(beta)-26\Common tools-Pharo 5.0 (beta)-26.image
Pharo5.0
Latest update: #50636
Unnamed

Virtual Machine
---------------
C:\Users\JeCisC\Desktop\PharoVMSpur\Pharo.exe
CoInterpreter * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
StackToRegisterMappingCogit * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
https://github.com/estebanlm/pharo-vm.git Commit:
6dc730123e8f2b0327839b235d16e0604a92288e Date: 2015-12-13 00:23:41 +0100
By: Esteban Lorenzano <[hidden email]> Jenkins build #456

Win32 built on Dec 13 2015 00:58:42 Compiler: 4.6.2
VMMaker versionString https://github.com/estebanlm/pharo-vm.git Commit:
6dc730123e8f2b0327839b235d16e0604a92288e Date: 2015-12-13 00:23:41 +0100
By: Esteban Lorenzano <[hidden email]> Jenkins build #456
CoInterpreter * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
StackToRegisterMappingCogit * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015

Operating System/Hardware
-------------------------
Win32 6.1 IX86

Operating System Details
------------------------
Operating System: Windows 7 Professional N (Build 7601 Service Pack 1)
        Registered Owner: JeCisC
        Registered Company:
        SP major version: 1
        SP minor version: 0
        Suite mask: 100
        Product type: 1



--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France

windowsDelay.csv (8K) Download Attachment
signature.asc (836 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Aliaksei Syrel
I think  we just found a serious bug!

Cyrill, could you perform a division in the same image you used for delay test and post result here?
123 / 2.0

On mac I get a float 61.5 

Cheers,
Alex

On Sat, Mar 12, 2016 at 8:33 PM, Cyril Ferlicot D. <[hidden email]> wrote:
Le 12/03/2016 18:47, Aliaksei Syrel a écrit :
> Hi
>
> At some point I got a feeling that actual Delay time is longer than
> expected. It is especially visible on small delays less than 100ms
> (otherwise difference is < 1%).
>
> Inline image 1
> Documentation says that _Delay waits approximately_ for specified amount
> of time. However, according to experimental data an actual difference is
> always positive with the value around 1.5-2 seconds. It is actually
> strange where such a constant difference, independent from delay length,
> comes from.
> Inline image 2
> To conclude, if you want to wait more precisely you need to create
> delays with duration 1.5 seconds less than expected. Also it would be
> interesting to test on different hardwares to make sure that difference
> stays constant (around 1.5-2s)
>
> I used the following script to gather data and save in .csv file
> http://ws.stfx.eu/DSCLG2ON0VBI
>
> Tested on:
> Pharo: #50636
> Spur-VM: #463
> OS: Mac OS Yosemite
> CPU: Intel Core i7 2.39 GHz
>
> Cheers,
> Alex
>

If you wish to compare I join a csv. This is my setup:

Image
-----
C:\Users\JeCisC\AppData\Roaming\Pharo\images\Common tools-Pharo 5.0
(beta)-26\Common tools-Pharo 5.0 (beta)-26.image
Pharo5.0
Latest update: #50636
Unnamed

Virtual Machine
---------------
C:\Users\JeCisC\Desktop\PharoVMSpur\Pharo.exe
CoInterpreter * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
StackToRegisterMappingCogit * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
https://github.com/estebanlm/pharo-vm.git Commit:
6dc730123e8f2b0327839b235d16e0604a92288e Date: 2015-12-13 00:23:41 +0100
By: Esteban Lorenzano <[hidden email]> Jenkins build #456

Win32 built on Dec 13 2015 00:58:42 Compiler: 4.6.2
VMMaker versionString https://github.com/estebanlm/pharo-vm.git Commit:
6dc730123e8f2b0327839b235d16e0604a92288e Date: 2015-12-13 00:23:41 +0100
By: Esteban Lorenzano <[hidden email]> Jenkins build #456
CoInterpreter * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015
StackToRegisterMappingCogit * VMMaker.oscog-rmacnak.1586 uuid:
8e44b2a7-68ee-4fc9-8513-a04520267053 Dec 13 2015

Operating System/Hardware
-------------------------
Win32 6.1 IX86

Operating System Details
------------------------
Operating System: Windows 7 Professional N (Build 7601 Service Pack 1)
        Registered Owner: JeCisC
        Registered Company:
        SP major version: 1
        SP minor version: 0
        Suite mask: 100
        Product type: 1



--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France

Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

CyrilFerlicot
Le 12/03/2016 20:44, Aliaksei Syrel a écrit :
> I think  we just found a serious bug!
>
> Cyrill, could you perform a division in the same image you used for
> delay test and post result here?
>
>     123 / 2.0
>

I get a BoxedFloat64(61.5)

--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France


signature.asc (836 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Aliaksei Syrel
I get a BoxedFloat64(61.5)

Very strange...

For some unexpected reason you get integers in delay test. But all values should be floats. I double checked the script..

There is a difference in arithmetic behaviour between mac and windows!

Cheers,
Alex

On Sat, Mar 12, 2016 at 8:48 PM, Cyril Ferlicot D. <[hidden email]> wrote:
Le 12/03/2016 20:44, Aliaksei Syrel a écrit :
> I think  we just found a serious bug!
>
> Cyrill, could you perform a division in the same image you used for
> delay test and post result here?
>
>     123 / 2.0
>

I get a BoxedFloat64(61.5)

--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France


Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Henrik Nergaard

The numbers in that csv from is in float, but with the fraction part is 0.

 

This is most likely caused by the fact that the precision for timing is in milliseconds, not microseconds.

Even the #primUTCMicrosecondsClock only updates per millisecond for me. (Windows).

 

((1 to: 100000) collect: [:n | Time primUTCMicrosecondsClock ] as: Set) asArray sort. “for me each entry is increased by 1000”

 

 

Best regards,

Henrik

 

From: Pharo-dev [mailto:[hidden email]] On Behalf Of Aliaksei Syrel
Sent: Saturday, March 12, 2016 9:01 PM
To: Pharo Development List <[hidden email]>
Subject: Re: [Pharo-dev] Comparison of actual and expected Delay length on small durations

 

I get a BoxedFloat64(61.5)

 

Very strange...

 

For some unexpected reason you get integers in delay test. But all values should be floats. I double checked the script..

 

There is a difference in arithmetic behaviour between mac and windows!

 

Cheers,

Alex

 

On Sat, Mar 12, 2016 at 8:48 PM, Cyril Ferlicot D. <[hidden email]> wrote:

Le 12/03/2016 20:44, Aliaksei Syrel a écrit :
> I think  we just found a serious bug!
>
> Cyrill, could you perform a division in the same image you used for
> delay test and post result here?
>
>     123 / 2.0
>

I get a BoxedFloat64(61.5)


--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France

 

Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

SergeStinckwich
In reply to this post by Aliaksei Syrel


Sent from my iPhone

On 12 mars 2016, at 21:01, Aliaksei Syrel <[hidden email]> wrote:

I get a BoxedFloat64(61.5)

Very strange...

For some unexpected reason you get integers in delay test. But all values should be floats. I double checked the script..

There is a difference in arithmetic behaviour between mac and windows!


If I remember correctly there is some differences in float operations between mac and windows. This is a problem for SciSmalltalk.


Cheers,
Alex

On Sat, Mar 12, 2016 at 8:48 PM, Cyril Ferlicot D. <[hidden email]> wrote:
Le 12/03/2016 20:44, Aliaksei Syrel a écrit :
> I think  we just found a serious bug!
>
> Cyrill, could you perform a division in the same image you used for
> delay test and post result here?
>
>     123 / 2.0
>

I get a BoxedFloat64(61.5)

--
Cyril Ferlicot

http://www.synectique.eu

165 Avenue Bretagne
Lille 59000 France


Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Ben Coman
In reply to this post by Aliaksei Syrel


On Sun, Mar 13, 2016 at 1:47 AM, Aliaksei Syrel <[hidden email]> wrote:
Hi

At some point I got a feeling that actual Delay time is longer than expected. It is especially visible on small delays less than 100ms (otherwise difference is < 1%).

Inline image 1
Documentation says that Delay waits approximately for specified amount of time. However, according to experimental data an actual difference is always positive with the value around 1.5-2 seconds. It is actually strange where such a constant difference, independent from delay length, comes from.
Inline image 2
To conclude, if you want to wait more precisely you need to create delays with duration 1.5 seconds less than expected. Also it would be interesting to test on different hardwares to make sure that difference stays constant (around 1.5-2s)

I used the following script to gather data and save in .csv file

Tested on:
Pharo: #50636
Spur-VM: #463
OS: Mac OS Yosemite
CPU: Intel Core i7 2.39 GHz


Nice analysis.  I've previously wondered about such an effect from resumptionTime being calculated by the high priority thread in #handleTimerEvent: and thus delayed by switching threads, rather than being calculated as-soon-as-possible by the low priority process when #schedule: is called.   I can't remember my line of reasoning, but doing it the low priority process seemed to open the potential for nasty race conditions, so I left it as I found it.  Perhaps we should take a time snapshot in the #schedule: and pass that through to #handleTimerEvent: similar to scheduledDelay.  Would you like to try that?

btw, I have some cleanup of DelayScheduler almost complete that I had meant to get into Pharo 5 earlier, but now I think best to wait for early Pharo 6.

cheers -ben 
Reply | Threaded
Open this post in threaded view
|

Re: Comparison of actual and expected Delay length on small durations

Ben Coman


On Sun, Mar 13, 2016 at 9:27 AM, Ben Coman <[hidden email]> wrote:


On Sun, Mar 13, 2016 at 1:47 AM, Aliaksei Syrel <[hidden email]> wrote:
Hi

At some point I got a feeling that actual Delay time is longer than expected. It is especially visible on small delays less than 100ms (otherwise difference is < 1%).

Inline image 1
Documentation says that Delay waits approximately for specified amount of time. However, according to experimental data an actual difference is always positive with the value around 1.5-2 seconds. It is actually strange where such a constant difference, independent from delay length, comes from.
Inline image 2
To conclude, if you want to wait more precisely you need to create delays with duration 1.5 seconds less than expected. Also it would be interesting to test on different hardwares to make sure that difference stays constant (around 1.5-2s)

I used the following script to gather data and save in .csv file

Tested on:
Pharo: #50636
Spur-VM: #463
OS: Mac OS Yosemite
CPU: Intel Core i7 2.39 GHz


Nice analysis.  I've previously wondered about such an effect from resumptionTime being calculated by the high priority thread in #handleTimerEvent: and thus delayed by switching threads, rather than being calculated as-soon-as-possible by the low priority process when #schedule: is called.   I can't remember my line of reasoning, but doing it the low priority process seemed to open the potential for nasty race conditions, so I left it as I found it.  Perhaps we should take a time snapshot in the #schedule: and pass that through to #handleTimerEvent: similar to scheduledDelay.  Would you like to try that?

btw, I have some cleanup of DelayScheduler almost complete that I had meant to get into Pharo 5 earlier, but now I think best to wait for early Pharo 6.

cheers -ben 

P.S.  I'm curious how you came to notice this.  I have a long term interest in Pharo as a soft-real time industrial control system, motion control system and robotics.  One option is using a protocol like EtherCAT which at the hardware level does microsecond time synchronisation of all nodes on the network, and every measurement is microsecond timestamped in the node before it is sent to the control system.  So your motion control algorithms can work with an extremely accurate timestamp of *exactly* when a measurement was taken, rather than when the measurement arrived at the control program which is dependent on the delay and jitter vagaries of communications hardware and CPU scheduling of the network stack and control programs.