Comments on: Precision delta time measurements

The delta-time function (or dt for short) is useful for timing your code. But, if you source it:

>> source delta-time
delta-time: make function! [[
   {Delta-time - return the time it takes to evaluate a block.}
   block [block!]
   /local start
][
   start: now/precise
   do block
   difference now/precise start
]]

you'll see that it uses now/precise.

A more accurate measurement would be to use stats/timer, which gives microsecond resolution.

The new function becomes:

delta-time: funct [
   {Delta-time - return the time it takes to evaluate a block.}
   block [block!]
][
   start: stats/timer
   do block
   to-time stats/timer - start / 1.0e6
]

Examples:

>> delta-time [loop 1000 [next "test"]]
== 0:00:00.000464
>> delta-time [wait 1]
== 0:00:01.001079

In A95, this change will be made, unless you know some reason not to.

Comments:

-pekr-
2-Nov-2009 15:28:27 OK, this is delta-time change. But why not to provide the option even for 'wait function? Reading linked older blog article, some ppl did not seem to be convinced 1ms is enough for some applications - maybe they want to do FullHD video editing using R3 and extensions :-)
Just curious, if it could be solved by e.g. wait/precise option? You mentioned that with all the OS/device/timeslicing precision, it does not make much sense, so I just wonder, if wait/precise, to those who really want it, would provide any advantage, or would it have kind of opposite effect, causing CPU to go to 100% etc.?
-pekr-
2-Nov-2009 15:35:45 btw - would it be possible to add another refinement to 'now? As for your code, I see no reason for the related functinality to be suddenly provided by different function - 'stats, unless there is really a need to consider it being a special case.
I propose:
now now/precise now/precise+
Maxim Olivier-Adlhoch
2-Nov-2009 18:08:27 funny that you should update this in R3 I did a HUGE analysis of iteration speeds in R2. And now precision effectively isn't enough for precise measurements.
R2 iterators test
I will eventually build the test as a stand-alone script for even more scripts and stats (RAM, GC, binding, etc)
this new version of the tests will be for R2 & R3.
Carl Sassenrath
2-Nov-2009 18:31:59 Pekr, you're making an incorrect assumption. In fact, WAIT does use that same method of high-resolution time differencing!
Did you try this:
>> dt [wait .00001] == 0:00:00.000011

There we ask to wait for 10 microseconds.
I'll update that older blog again to make sure others don't misunderstand it as well.
-pekr-
2-Nov-2009 20:49:53 aha, so it is there, it just decides, which method will be used, upon the requested granularity. All is well then ...
Ladislav
3-Nov-2009 9:32:53 Warning! A shameless plug below!
When I use the new Delta-time implementation to measure the execution time of the code block from the article, the result has a 47% error, while my Time-block function defined in: http://www.fm.tul.cz/~ladislav/rebol/timblk.r available for years and working even in R2 makes a measurement having less than 5% error.
Brian Hawley
3-Nov-2009 14:52:39 Ladislav, is that error or variance?
If you run on a multitasking OS (particularly Windows) there will be a lot of variance between different runs, mostly due to the inconsistent overhead of background processes, or variable CPU speed for power management. Your timblk smooths over that variance by running the code many times and then averaging the time.
DT only runs the block once, so it is more subject to the variance in available resources. However, this also makes DT more safe for testing the timing of modifying code, since any changes made will only be made once.
Your timblk can be made more precise for its R3 version by using the same stats/timer method as DT.
Ladislav
4-Nov-2009 5:06:11 "...is that error or variance?" - actually, it is error, if I understand it correctly! See this:
>> start: now/precise start-t: stats/timer loop 10000000000 [] stop: now/precise stop-t: stats/timer == 1659291524
>> to decimal! difference start stop == -82.696
>> to decimal! difference stop start == 82.696
>> stop-t - start-t * 1e-6 == 121.688792
Ladislav
4-Nov-2009 5:31:33 According to the above measurement, the Stats/timer update frequency is (on my machine running Windows 7 currently) not 1000000 Hz, but 1471241 Hz, i.e. 47% faster!
Carl Sassenrath
4-Nov-2009 12:41:01 So, that's a bug.
BTW, your time seems quite fast. What kind of machine? Are you overclocking your CPU (although, one would think that would make no difference in the high precision timer circuits.)
Ladislav
4-Nov-2009 13:29:44 My processor is AMD Athlon II X2 250 running at 3.0 GHz, i.e. not overclocked.
Carl Sassenrath
4-Nov-2009 14:26:04 There appears to be a problem in the BIOS on some motherboards -- they do not properly init multiple CPU cores causing QueryPerformanceCounter() times to be inaccurate because the start and stop times may be from different CPU cores.
"Recently a range of dual-core CPU users - those who have Pentium D, AMD X2 and even Pentium 4 HyperThreading CPUs - are complaining of odd game problems, such as random crashes to desktop and lockups. It's happened due to motherboard developers incorrectly initialize processors. If any program use processor tick counter, this program can fail on any dual-core CPU system." -- ice-graphics.com
Do you think it could be what's happening?
Ladislav
4-Nov-2009 14:43:23 I guess, that it is possible, have to check that somehow. I am using the latest Bios available from Gigabyte, though.
-pekr-
4-Nov-2009 15:47:15 I will try to find some info, but what I have read, when researching IO (Console), was some such issue of random time skips happening occassionaly. There is also mention of using SetThreadAffinityMask in MSDN article:
On a multiprocessor computer, it should not matter which processor is called. However, you can get different results on different processors due to bugs in the basic input/output system (BIOS) or the hardware abstraction layer (HAL). To specify processor affinity for a thread, use the SetThreadAffinityMask function.

... dunno if it could help ...
Ladislav
4-Nov-2009 17:07:54 ...but this does not look random at all, the result is quite consistent, showing, that Stats/timer is 47% faster.
-pekr-
4-Nov-2009 20:19:37 Is QueryPerformanceFrequency used, along to QueryPerformanceCounter?
Ladislav
5-Nov-2009 5:55:11 When using QueryPerformanceFrequency in R2, I get 2943046, i.e. even more, and it looks like working reliably.
Carl Sassenrath
5-Nov-2009 17:44:41 Pekr: yes of course, QueryPerformanceFrequency and QueryPerformanceCounter are always called together, otherwise there is no way to achieve a time-base reference.
Ladislav: another possible problem may be related to integer 64 division.
Steeve
7-Nov-2009 12:07:15 My 2 cents. The modified dp i use
dp: funco [ "Delta-profile of running a specific block." block [block!] /default "Do not adjust the result" /local start diff ][ diff: first [#[function! [[s e][foreach v s [set v e/:v - get v] s]]]] start: copy stats/profile do block diff start copy stats/profile unless default [ start: diff dp/default [] start start/timer: to time! start/timer / 1000000 ] start ]

Comments on: Precision delta time measurements

Comments:

Post a Comment: