Win 7 GetTickCount() weirdness

[mar]

I'm using QueryPerformanceCounter() but I will change to GetTickCount() because I read it can cause problems on multi cores machines.

The problem with performance counter is that it uses/used rdtsc. This caused problems on some early multicore CPUs (because each core had its own timestamp counter). There is also a problem with turbo-boost. I'm not sure if QueryPerformanceCounter still uses rdtsc or if they use something else but it's unreliable (at least on Windows versions which use rdtsc).
GetTickCount() is ok except that it has granularity not suitable for precise timing.
As I wrote earlier the only reliable way (AFAIK) to do msec-precise timing under Windows is to use timeGetTime().
However you have to call timeBeginPeriod(1) at the beginning of your program and timeEndPeriod(1) at the end.
The only problem is it changes timer interrupt frequency to 1000Hz which may cause problems on very old hardware.

[jdart]

The only problem is it changes timer interrupt frequency to 1000Hz which may cause problems on very old hardware.

It also has a performance cost, at least last time I tried it, it did.

-Jon

[bob]

I always use the Windows call GetTickCount() to control the thinking time of my engines. But when I was working on implementing pondering for my engine HaChu, I noticed (at 40 moves/min) that on the first move it would only search 1 ply (and thus have no ponder move). The time management gives it 147 msec to start the 2-ply iteration, but after the first iteration (47 nodes!) it thinks this time has already elapsed (it reports 17 centi-sec in the thinking output).

Of course I let it print the start and stop time for debugging (immediately flushing the output), and there appears to be only a few (~10) msec between reception of these start and stop messages by WinBoard. (The clock of which now also seems to tick every msec, which is also a novelty, as on all my other machines the timestamps in the debug file always increase in steps of ~16 msec.)

The engine gives debug output for every root move, so I let it print GetTickCount() there as well, to see where this discrepancy between engine-measured time and GUI-measured time occurs. This seems to make the problem go away, however: GetTickCount() now thinks hardly any time elapses during the 1-ply and 2-ply iteration (it increments in steps of ~16 msec, so it is hard to see exactly how much), and it nicely reaches 4 ply. But in other places (where I use the search to create a list of legal moves) it seems there are ticks missing. E.g. a part of the 1-ply iteration:

Code: Select all

1844 >first : usermove 1845 >first : h3h4
1977 <first : # in (mode = 1,0): put
1977 <first : # in (mode = 1,0): time
1977 <first : # in (mode = 1,0): otim
1977 <first : # in (mode = 1,0): usermove
....
1988 <first : 0: 1:1  78  610aa c8c7            1     14  (16499944)
1988 <first : 0: 1:1  79  620ac e8e7            1     14
1988 <first : 0: 1:1  79  620ac e8e7            5     14  (16499944)
1989 <first : 0: 1:1  80  628ad f8f7            5     14
1989 <first : 0: 1:1  80  628ad f8f7           -6     14  (16499944)
1989 <first : 0: 1:1  81  630ae g8g7           -6     14
1989 <first : 0: 1:1  81  630ae g8g7           -1     14  (16499944)
1989 <first : 0: 1:1  82  638af h8h7           -1     14
1989 <first : 0: 1:1  82  638af h8h7            4     14  (16499944)
1989 <first : 0: 1:1  83  648b1 j8j7            4     14
1989 <first : 0: 1:1  83  648b1 j8j7            1     14  (16499944)
2003 <first : 0: 1:1  84  650b2 k8k7            1     14
2003 <first : 0: 1:1  84  650b2 k8k7           -4     14  (16499944)
2003 <first : 0: 1:1  85  658b3 l8l7           -4     14
2003 <first : 0: 1:1  85  658b3 l8l7           -6     14  (16500085)

The first column is the WinBoard time stamp, the last number the GetTickCount(). In the last move the tick count suddenly jumps 141 msec!

There is a similar discontinuity in the GUI time stamps after sending the move that triggered all this engine activity (133 msec). It is almost like the programs can be temporarily suspended for periods > 100 msec. This is on a quad-core i7, however, with a single-threaded engine and no other explicit tasks running...

Has anyone seen similar erratic behavior with GetTickCount()?

All operating systems I know of exhibit this behavior. They might offer high-resolution timers, but they typically update the timer in "bursts". The worst case is where you sample the time to start timing, and one instruction later the timer has been updated by adding some constant to it. Making it look like that one instruction took several ms of time.

One solution is to sample the time over and over until it changes, then start the code you want to time. Not good for chess, obviously, because you waste time waiting for the timer to tick over...

Also note that your "change" gets you to ms resolution. Meaning your accuracy is +/- 0.9ms, which might not be enough if you want to play very fast games.

[Ajedrecista]

Hello:

This post is slightly off-topic, but I wanted to agree that some timers have a resolution of 1/64 of second, that is, 0.015625 seconds.

I wrote a short Fortran 95 programme to show it:

Code: Select all

program tiempo
implicit none
integer::i
integer,parameter::n=100000  ! 1e+5
real::t_CLOCK(n)
real(2)::a(n),t_CPU_TIME(n),t_DCLOCK(n)
do i=1,n
  a(i)=i*1d0
  call cpu_time(t_CPU_TIME(i))
end do
do i=1,n
  a(i)=i*1d0
  call clock@(t_CLOCK(i))
end do
do i=1,n
  a(i)=i*1d0
  call dclock@(t_DCLOCK(i))
end do
open(unit=11,file='Output_CPU_TIME.txt',status='unknown',action='write')
do i=1,n
  write(11,*) t_CPU_TIME(i)
end do
close(11)
open(unit=101,file='Output_CLOCK.txt',status='unknown',action='write')
do i=1,n
  write(101,*) t_CLOCK(i)
end do
close(101)
open(unit=110,file='Output_DCLOCK.txt',status='unknown',action='write')
do i=1,n
  write(110,*) t_DCLOCK(i)
end do
close(110)
end program

I used three routines of Silverfrost Plato IDE compiler for Fortran 95: CPU_TIME(), CLOCK@() and DCLOCK@(). I recorded all the times given by those three different timers and printed them in three separated Notepads. The result is that each Notepad has lots of the same numbers and then sudden gaps of 1/64 of second. I copy here the only different times (in seconds, of course):

Code: Select all

CPU_TIME()

0.359375000000
0.375000000000
0.390625000000
0.406250000000
0.421875000000
0.437500000000

Code: Select all

CLOCK@()

5.10900
5.12500
5.14100
5.15600

Code: Select all

DCLOCK@()

5.15599999999
5.17199999999
5.18799999999

CPU_TIME() is the best for show the granularity of 0.015625 seconds. Furthermore: 0.359375/0.015625 = 23 (an exact integer), so the times printed in Output_CPU_TIME.txt are 23/64, 24/64, 25/64, 26/64, 27/64 and 28/64 of second.

I did 100000 calls in each do loop, but the total elapsed time is very different for each timer. I ran the programme only once. My PC has Windows XP (32-bit).

I hope that this info will be somewhat useful.

Regards from Spain.

Ajedrecista.