Comparison of actual and expected Delay length on small durations
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%). [image: 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. [image: 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
*Difference is in milliseconds*, sorry :) On Sat, Mar 12, 2016 at 6:47 PM, Aliaksei Syrel <alex.syrel@gmail.com> 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%).
[image: 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. [image: 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
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 <estebanlm@gmail.com> 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 <estebanlm@gmail.com> 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
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. <cyril.ferlicot@gmail.com
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 <estebanlm@gmail.com> 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 <estebanlm@gmail.com> 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
165 Avenue Bretagne Lille 59000 France
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
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. <cyril.ferlicot@gmail.com
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
165 Avenue Bretagne Lille 59000 France
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:pharo-dev-bounces@lists.pharo.org] On Behalf Of Aliaksei Syrel Sent: Saturday, March 12, 2016 9:01 PM To: Pharo Development List <pharo-dev@lists.pharo.org> 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. <cyril.ferlicot@gmail.com<mailto:cyril.ferlicot@gmail.com>> 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
Sent from my iPhone On 12 mars 2016, at 21:01, Aliaksei Syrel <alex.syrel@gmail.com> 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. <cyril.ferlicot@gmail.com> 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
165 Avenue Bretagne Lille 59000 France
On Sun, Mar 13, 2016 at 1:47 AM, Aliaksei Syrel <alex.syrel@gmail.com> 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%).
[image: 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. [image: 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
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
On Sun, Mar 13, 2016 at 9:27 AM, Ben Coman <btc@openinworld.com> wrote:
On Sun, Mar 13, 2016 at 1:47 AM, Aliaksei Syrel <alex.syrel@gmail.com> 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%).
[image: 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. [image: 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
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.
participants (5)
-
Aliaksei Syrel -
Ben Coman -
Cyril Ferlicot D. -
Henrik Nergaard -
serge.stinckwich＠gmail.com